Performance Issue while using Metal backend.

[Jasonsey]

Hi there,

Candle is really a great project when using Rust. But currently I faced some performance Issue when I use it to infer my Model.

Here is some of my model code:

impl Module for RRDB {
    fn forward(&self, x: &Tensor) -> Result<Tensor> {
        let start = Instant::now();
        let oup = self.rdb1.forward(x)?;
        let oup = self.rdb2.forward(&oup)?;
        let oup = self.rdb3.forward(&oup)?;
        let res = oup * 0.2 + x;
        println!("block process time: {:?}", start.elapsed());
        res
    }
}

After I do this forward function manny times, the time consuming is increasing. Here is the log:

block process time: 2.047125ms
block process time: 1.727084ms
block process time: 1.85325ms
block process time: 1.602167ms
block process time: 1.691666ms
block process time: 1.804833ms
block process time: 1.78675ms
block process time: 1.742667ms
block process time: 1.581042ms
block process time: 1.644833ms
block process time: 1.772917ms
block process time: 1.695958ms
block process time: 1.766334ms
block process time: 1.623375ms
block process time: 1.742208ms
block process time: 1.675958ms
block process time: 1.771334ms
block process time: 236.509ms
block process time: 503.890583ms
block process time: 390.076375ms
block process time: 495.903084ms
block process time: 529.992666ms
block process time: 366.003875ms
block process time: 495.694083ms
block process time: 390.461375ms
block process time: 497.969958ms
block process time: 498.7325ms
block process time: 403.164125ms
block process time: 488.229458ms
block process time: 524.081875ms
block process time: 375.679167ms
block process time: 508.565042ms
block process time: 389.132209ms
block process time: 508.387208ms
block process time: 500.397959ms
block process time: 401.458583ms
block process time: 490.374167ms
block process time: 518.663584ms
block process time: 376.272792ms
block process time: 518.60275ms
block process time: 1.472589375s
block process time: 328.865375ms
block process time: 322.741459ms
block process time: 250.503333ms
block process time: 316.479292ms
block process time: 317.622416ms
block process time: 242.031125ms
block process time: 326.601459ms
block process time: 251.282875ms
block process time: 323.213208ms
block process time: 319.51025ms
block process time: 256.726084ms
block process time: 314.952541ms
block process time: 330.990334ms
block process time: 240.115625ms
block process time: 325.475333ms
block process time: 249.119167ms
block process time: 326.153334ms
block process time: 319.268833ms
block process time: 255.009291ms
block process time: 314.721042ms
block process time: 333.955625ms
block process time: 241.245666ms
block process time: 1.16066575s
block process time: 443.387583ms
block process time: 566.287125ms
block process time: 554.786625ms
block process time: 431.030416ms
block process time: 544.772083ms
block process time: 568.671916ms
block process time: 410.647042ms
block process time: 558.133167ms
block process time: 425.856291ms
block process time: 556.451292ms
block process time: 544.14825ms
block process time: 440.875167ms
block process time: 539.090792ms
block process time: 575.805542ms
block process time: 412.616417ms
block process time: 557.536041ms
block process time: 426.443416ms
block process time: 566.2835ms
block process time: 544.170708ms
block process time: 434.747875ms
block process time: 535.491166ms
block process time: 548.576334ms
block process time: 1.64796325s
block process time: 348.008166ms
block process time: 282.976ms
block process time: 348.38475ms
block process time: 366.042791ms
block process time: 267.093916ms
block process time: 346.409167ms
block process time: 348.611666ms
block process time: 284.104292ms
block process time: 360.060416ms
block process time: 271.554ms
block process time: 357.186167ms
block process time: 350.56875ms
block process time: 277.07075ms
block process time: 350.898ms
block process time: 350.061208ms
block process time: 282.163458ms
block process time: 346.33075ms
block process time: 368.18625ms
block process time: 263.653083ms
block process time: 358.285875ms
block process time: 273.358ms
block process time: 362.535459ms
block process time: 1.015997542s
block process time: 88.540916ms
block process time: 109.382833ms
block process time: 109.310416ms
block process time: 87.187625ms
block process time: 114.729167ms
block process time: 87.404291ms
block process time: 111.601917ms
block process time: 110.608084ms
block process time: 89.529708ms
block process time: 108.535625ms
block process time: 114.542375ms
block process time: 84.9315ms
block process time: 112.986166ms
block process time: 87.082083ms
block process time: 110.971542ms
block process time: 112.866ms
block process time: 89.563458ms
block process time: 108.4445ms
block process time: 115.158416ms
block process time: 83.165875ms
block process time: 113.004167ms
block process time: 87.176333ms
block process time: 344.457458ms
block process time: 72.254792ms
block process time: 56.214959ms
block process time: 71.726666ms
block process time: 70.487208ms
block process time: 57.035167ms

Does anyone know why the time consuming can change from 1ms to 500ms?

[Jasonsey]

BTW, if I infer this model with PyTorch it's very fast. But when I translate the model code to candle, it's about 5 times slower then torch model. Is it possible this issue can cause the result?

[LaurentMazare]

Just to mention something that may be a bit obvious: metal is an asynchronous api (same as cuda) so in order to time things properly you have to insert some "synchronise" calls to ensure that the code has fully run up to the point where you make the time measurements.