Profiler slows down my code

[azouaoui-cv]

Hello fellow PL users :)

PL version used: 1.0.5

I'm experiencing some weird slowness when training basic CV models that seem to be related to the profiler.
I'm using the simple profiler by default in my Trainer.
I first noticed that the optimizer_step was taking a large amount of time which should not be the case. See simple profiler output below for a single epoch on cifar10:

Profiler Report

Action                  |  Mean duration (s)    |  Total time (s) 
-----------------------------------------------------------------
on_fit_start            |  0.00010359           |  0.00010359     
on_validation_start     |  0.00026737           |  0.00053473     
on_validation_epoch_start       |  6.7838e-05           |  0.00013568     
on_validation_batch_start       |  8.639e-05            |  0.0069976      
validation_step_end     |  3.367e-05            |  0.0027272      
on_validation_batch_end |  0.00046458           |  0.037631       
on_validation_epoch_end |  6.8574e-05           |  0.00013715     
on_validation_end       |  0.44333              |  0.88666        
on_train_start          |  0.00045575           |  0.00045575     
on_epoch_start          |  0.0003592            |  0.0003592      
on_train_epoch_start    |  0.00026519           |  0.00026519     
get_train_batch         |  0.0012642            |  0.49431        
on_batch_start          |  4.4949e-05           |  0.017575       
on_train_batch_start    |  0.0055252            |  2.1604         
training_step_end       |  2.5107e-05           |  0.0098168      
model_forward           |  0.016551             |  6.4714         
model_backward          |  0.025459             |  9.9544         
on_after_backward       |  3.5052e-05           |  0.013705       
optimizer_step          |  0.047881             |  18.721         
on_batch_end            |  4.5023e-05           |  0.017604       
on_train_batch_end      |  0.0057992            |  2.2675         
on_epoch_end            |  0.00066691           |  0.00066691     
on_train_epoch_end      |  2.5967e-05           |  2.5967e-05     
on_train_end            |  0.00032465           |  0.00032465  

I then investigated further using the advanced profile to pinpoint the function call that was slow and found out that {method 'enable' of '_lsprof.Profiler' objects} was the culprit in optimizer_step. See the output below:

18 Profile stats for: optimizer_step
 17          21114 function calls in 18.437 seconds
 16 
 15    Ordered by: cumulative time
 14 
 13    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 12       391    0.006    0.000   18.437    0.047 accelerator.py:103(optimizer_step)
 11       391    0.003    0.000   18.429    0.047 lightning.py:1125(optimizer_step)
 10       391    0.003    0.000   18.426    0.047 lr_scheduler.py:62(wrapper)
  9       391    0.002    0.000   18.424    0.047 grad_mode.py:23(decorate_context)
  8       391    0.001    0.000   18.417    0.047 sgd.py:75(step)
  7       391    0.001    0.000   18.415    0.047 training_loop.py:709(train_step_and_backward_closure)
  6       391    0.001    0.000   18.415    0.047 training_loop.py:807(training_step_and_backward)
  5       391    0.004    0.000   18.414    0.047 training_loop.py:306(training_step)
  4       391    0.001    0.000   18.387    0.047 contextlib.py:107(__enter__)
  3       391    0.000    0.000   18.386    0.047 {built-in method builtins.next}
  2       391    0.000    0.000   18.386    0.047 profilers.py:56(profile)
  1       391    0.001    0.000   18.385    0.047 profilers.py:212(start)                                                                                                                                          
  0       391   18.385    0.047   18.385    0.047 {method 'enable' of '_lsprof.Profiler' objects}                                                                                                                  
  1       391    0.003    0.000    0.010    0.000 step_result.py:28(__init__)                                                                                                                                      
  2       782    0.008    0.000    0.010    0.000 module.py:781(__setattr__)                                                                                                                                       
  3       391    0.003    0.000    0.007    0.000 os.py:684(__setitem__)                                                                                                                                           
  4       782    0.001    0.000    0.003    0.000 properties.py:209(get_model)                                                                                                                                     
  5      3519    0.003    0.000    0.003    0.000 {built-in method builtins.isinstance}                                                                                                                            
  6       391    0.003    0.000    0.003    0.000 {built-in method posix.putenv}                                                                                                                                   
  7       391    0.001    0.000    0.002    0.000 grad_mode.py:85(__enter__)                                                                                                                                       
  8       782    0.001    0.000    0.002    0.000 model_connector.py:54(get_model)                                                                                                                                 
  9       391    0.002    0.000    0.002    0.000 grad_mode.py:80(__init__)                                                                                                                                        
 10       782    0.001    0.000    0.002    0.000 os.py:754(encode)                                                                                                                                                
 11       391    0.000    0.000    0.001    0.000 contextlib.py:237(helper)                                                                                                                                        
 12       391    0.001    0.000    0.001    0.000 contextlib.py:81(__init__)                                                                                                                                       
 13       391    0.001    0.000    0.001    0.000 grad_mode.py:166(__init__)                                                                                                                                       
 14       391    0.001    0.000    0.001    0.000 grad_mode.py:124(__enter__)                                                                                                                                      
 15       782    0.001    0.000    0.001    0.000 {method 'encode' of 'str' objects}                                                                                                                               
 16      1173    0.001    0.000    0.001    0.000 {built-in method torch._C.is_grad_enabled}                                                                                                                       
 17      2346    0.001    0.000    0.001    0.000 {method 'get' of 'dict' objects}                                                                                                                                 
 18       782    0.000    0.000    0.000    0.000 {built-in method torch._C._set_grad_enabled}                                                                                                                     
 19       391    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}                                                                                                                               
 20       391    0.000    0.000    0.000    0.000 _jit_internal.py:750(is_scripting)     

By further investigating, I was able to see that {method 'enable' of '_lsprof.Profiler' objects} is only set to enable in model_forward and optimizer_step. For some reason it is much faster in model_forward. See below:

1 Profile stats for: model_forward
  2          721786 function calls (692461 primitive calls) in 6.574 seconds
  3 
  4    Ordered by: cumulative time
  5 
  6    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  7       391    0.001    0.000    6.397    0.016 gpu_accelerator.py:57(training_step)
  8       391    0.004    0.000    6.395    0.016 gpu_accelerator.py:66(__training_step)
  9       391    0.009    0.000    6.276    0.016 base.py:54(training_step)
 10 14467/391    0.119    0.000    5.970    0.015 module.py:715(_call_impl)
 11       391    0.013    0.000    5.962    0.015 tiny_scnets.py:153(forward)
 12      5083    1.455    0.000    5.783    0.001 sclayer.py:139(forward)
 13      1173    0.005    0.000    5.223    0.004 container.py:115(forward)
 14      2346    0.014    0.000    5.199    0.002 tiny_scnets.py:57(forward)
 15     25415    1.559    0.000    1.559    0.000 {built-in method conv2d}
 16     25415    0.611    0.000    1.210    0.000 ops.py:27(shifted_relu)
 17      5083    0.173    0.000    0.638    0.000 batchnorm.py:97(forward)
 18     25415    0.054    0.000    0.598    0.000 functional.py:1124(relu)
 19     25415    0.539    0.000    0.539    0.000 {built-in method relu}
 20      5083    0.027    0.000    0.393    0.000 functional.py:2040(batch_norm)
 21      5083    0.019    0.000    0.364    0.000 grad_mode.py:23(decorate_context)
 22      5083    0.334    0.000    0.334    0.000 {built-in method batch_norm}
 23      5083    0.034    0.000    0.291    0.000 sclayer.py:130(clamp_params)
 24     10166    0.249    0.000    0.249    0.000 {method 'clamp' of 'torch._C._TensorBase' objects}
 25       391    0.002    0.000    0.176    0.000 trainer.py:826(call_hook)
 26       391    0.001    0.000    0.172    0.000 contextlib.py:107(__enter__)
 27       391    0.000    0.000    0.171    0.000 {built-in method builtins.next}
 28       391    0.000    0.000    0.171    0.000 profilers.py:56(profile)
 29       391    0.001    0.000    0.170    0.000 profilers.py:212(start)
 30       391    0.170    0.000    0.170    0.000 {method 'enable' of '_lsprof.Profiler' objects}
 31      5083    0.154    0.000    0.154    0.000 {method 'add_' of 'torch._C._TensorBase' objects}

I looked up on Google what could be the issue but so far I've only identified that nested profilers are a bad practice but I do not even know if this is what happening here.

Questions:

• Is this the intended behavior?
• Should I submit an Issue?
• Should I upgrade to the latest stable PL version?

Any help would be greatly appreciated.
Have a nice day!

Alex

[azouaoui-cv]

UPDATE

Updating to the latest stable PL release (v.1.2.0) did not solve it:

Profile stats for: optimizer_step_and_closure_0                                  
  1          12903 function calls in 18.582 seconds                                       
  2                                                                          
  3    Ordered by: cumulative time                                                                               
  4                                                                       
  5    ncalls  tottime  percall  cumtime  percall filename:lineno(function)         
  6       391    0.002    0.000   18.582    0.048 accelerator.py:265(optimizer_step)
  7       391    0.001    0.000   18.578    0.048 accelerator.py:282(run_optimizer_step)
  8       391    0.002    0.000   18.577    0.048 training_type_plugin.py:159(optimizer_step)     
  9       391    0.002    0.000   18.575    0.048 lr_scheduler.py:62(wrapper)                    
 10       391    0.002    0.000   18.573    0.048 grad_mode.py:23(decorate_context)                   
 11       391    0.002    0.000   18.566    0.047 sgd.py:75(step)                     
 12       391    0.001    0.000   18.564    0.047 training_loop.py:643(train_step_and_backward_closure)
 13       391    0.001    0.000   18.563    0.047 training_loop.py:732(training_step_and_backward)
 14       391    0.001    0.000   18.561    0.047 contextlib.py:107(__enter__)                                
 15       391    0.000    0.000   18.560    0.047 {built-in method builtins.next}
 16       391    0.000    0.000   18.560    0.047 profilers.py:62(profile)          
 17       391    0.001    0.000   18.559    0.047 profilers.py:250(start)              
 18       391   18.559    0.047   18.559    0.047 {method 'enable' of '_lsprof.Profiler' objects}
 19       391    0.001    0.000    0.002    0.000 grad_mode.py:85(__enter__)          
 20       391    0.002    0.000    0.002    0.000 grad_mode.py:80(__init__)    
 21       391    0.000    0.000    0.002    0.000 accelerator.py:104(lightning_module)        
 22       391    0.000    0.000    0.002    0.000 training_type_plugin.py:91(lightning_module)

[justusschock]

Hi @inzouzouwetrust, are you running on GPU? If so can you try either on CPU or launch the script with CUDA_LAUNCH_BLOCKING=1 ? Because it might be, that some of these things may not be timed correctly due to the asynchronity of CUDA calls.

[azouaoui-cv]

Hello @justusschock,
I just ran the following tests:

---

CUDA_LAUNCH_BLOCKING=1 python train.py training.epochs=1 trainer.profiler=simple

which gives me this output:

0 Profile stats for: optimizer_step_and_closure_0                                  
  1          12903 function calls in 38.935 seconds                            
  2                                                                                    
  3    Ordered by: cumulative time                                            
  4                                                                                 
  5    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  6       391    0.002    0.000   38.934    0.100 accelerator.py:265(optimizer_step)
  7       391    0.001    0.000   38.930    0.100 accelerator.py:282(run_optimizer_step)
  8       391    0.002    0.000   38.929    0.100 training_type_plugin.py:159(optimizer_step)
  9       391    0.003    0.000   38.927    0.100 lr_scheduler.py:62(wrapper)      
 10       391    0.002    0.000   38.925    0.100 grad_mode.py:23(decorate_context)       
 11       391    0.001    0.000   38.918    0.100 sgd.py:75(step)                                                
 12       391    0.001    0.000   38.916    0.100 training_loop.py:643(train_step_and_backward_closure)
 13       391    0.001    0.000   38.915    0.100 training_loop.py:732(training_step_and_backward)
 14       391    0.001    0.000   38.912    0.100 contextlib.py:107(__enter__)                    
 15       391    0.000    0.000   38.911    0.100 {built-in method builtins.next}                     
 16       391    0.000    0.000   38.911    0.100 profilers.py:62(profile)                       
 17       391    0.001    0.000   38.911    0.100 profilers.py:250(start)        
 18       391   38.910    0.100   38.910    0.100 {method 'enable' of '_lsprof.Profiler' objects}

---

CUDA_LAUNCH_BLOCKING=1 python train.py training.epochs=1 trainer.profiler=advanced

which gives me this output:

Profiler Report

Action                                  |  Mean duration (s)    |Num calls              |  Total time (s)       |  Percentage %         |
------------------------------------------------------------------------------------------------------------------------------------
Total                                   |  -                    |_                      |  73.107               |  100 %                |
------------------------------------------------------------------------------------------------------------------------------------
run_training_epoch                      |  62.507               |1                      |  62.507               |  85.5                 |
run_training_batch                      |  0.10725              |391                    |  41.936               |  57.362               |
optimizer_step_and_closure_0            |  0.097117             |391                    |  37.973               |  51.941               |

---

On CPU:

python train.py trainer=debug_cpu trainer.profiler=simple

which gives me this output:

Profiler Report

Action                                  |  Mean duration (s)    |Num calls              |  Total time (s)       |  Percentage %         |
------------------------------------------------------------------------------------------------------------------------------------
Total                                   |  -                    |_                      |  11.905               |  100 %                |
------------------------------------------------------------------------------------------------------------------------------------
run_training_epoch                      |  8.1349               |1                      |  8.1349               |  68.329               |
get_train_batch                         |  4.1752               |1                      |  4.1752               |  35.07                |
run_training_batch                      |  2.1171               |1                      |  2.1171               |  17.783               |
optimizer_step_and_closure_0            |  2.1138               |1                      |  2.1138               |  17.754               |

---

As you can see, the time optimizer_step_and_closure_0 takes is still significant in case 1 & 2.
When I'm running on the CPU it is less clear because I'm using the fast_dev_run Trainer flag but I still believe 17% spent in optimizer_step is a lot. Do you agree?

Thanks for your interest!

[justusschock]

Hi @inzouzouwetrust.

Thanks for re-running. I don't think this is actually a significant amount of time. Let me quickly explain why I think so:

The snippet you posted says it's running optimizer_step_and_closure. The important part here is the closure. The actual training step is run within the optimizer's closure meaning that the time for the optimizer step also contains the time for the whole training step (forward + backward).
See here for more details on closure with PyTorch optimizers :)