Timing one training batch correctly
🐛 Bug
I'm trying to time a training batch (model forward, backward and optimizer step) by doing the following:
    def on_train_batch_end(self, trainer, pl_module, outputs, batch, batch_idx, dataloader_idx):
        self.train_time_epoch_list.append(time.time() - self.t0) #Measures ~time for forward + backward + optimizer_step

    def on_train_batch_start(self, trainer, pl_module, batch, batch_idx, dataloader_idx):
        self.t0 = time.time()

As a sanity check, I tried to confirm with profiler=True set in my trainer.
Profiler Report

Action              	|  Mean duration (s)	|  Total time (s) 
-----------------------------------------------------------------
on_fit_start        	|  0.0002028      	|  0.0002028      
on_train_start      	|  0.018464       	|  0.018464       
on_epoch_start      	|  0.00025359     	|  0.00025359     
on_train_epoch_start	|  2.099e-05      	|  2.099e-05      
get_train_batch     	|  0.039579       	|  1.0686         
on_batch_start      	|  3.1986e-05     	|  0.00086362     
on_train_batch_start	|  2.5267e-05     	|  0.0006822      
training_step_end   	|  1.5809e-05     	|  0.00042684     
model_forward       	|  0.085158       	|  2.2993         
model_backward      	|  0.17356        	|  4.6862         
on_after_backward   	|  2.5937e-05     	|  0.00070029     
optimizer_step      	|  0.2901         	|  7.8326         
on_before_zero_grad 	|  2.1495e-05     	|  0.00058038     
on_batch_end        	|  0.00023385     	|  0.0063139      
on_train_batch_end  	|  0.0010522      	|  0.028408       
on_validation_start 	|  0.00022554     	|  0.00067661     
on_validation_epoch_start	|  1.7601e-05     	|  5.2804e-05     
on_validation_batch_start	|  0.00020385     	|  0.00061156     
validation_step_end 	|  4.1274e-05     	|  0.00012382     
on_validation_batch_end	|  0.00060834     	|  0.001825       
on_validation_epoch_end	|  3.8694e-05     	|  0.00011608     
on_validation_end   	|  10.084         	|  30.253         
on_epoch_end        	|  2.2369e-05     	|  2.2369e-05     
on_train_epoch_end  	|  0.001022       	|  0.001022       
on_train_end        	|  0.00019247     	|  0.00019247     

[0.6943173408508301, 0.2949495315551758, 0.2607576847076416, 0.2683448791503906, 0.2595827579498291, 0.26221323013305664, 0.27995753288269043, 0.2629232406616211, 5.543228387832642, 0.26635313034057617, 0.25763630867004395, 0.2739405632019043, 0.32945823669433594, 0.3239474296569824, 0.3061668872833252, 0.3066873550415039, 13.223016262054443, 0.30397772789001465, 0.29555439949035645, 0.2981913089752197, 0.2988457679748535, 0.29936695098876953, 0.29789280891418457, 0.29648828506469727, 12.333884477615356, 0.29997682571411133, 0.30209898948669434]


The list numbers returned from call back hook and profiler don't add up. ie from profiler, each batch should approximately take
0.085158  (fprop) + 0.17356 (bprop) + 0.2901 (optim step).  Confirming here that it is what is being measured with the hooks. Am I missing something?
Expected behavior
expected fprop + bprop + optim_step to add up to callback hook time