All time taken by {method 'enable' of '_lsprof.Profiler' objects} in Advanced profiler output

[SeguinBe]

Hi,

I was trying to understand what is the bottleneck in my network, and was playing with the simple and advanced profiler bundled directly in lightning.

The output I got from the simple profiler seemed correct, while not terribly informative in my case. However, the output of the advanced profiler is a bit confusing with almost all the tottime being spent in {method 'enable' of '_lsprof.Profiler' objects}

Excerpt below:

Profile stats for: model_forward
         108402 function calls (107156 primitive calls) in 5.595 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1246    0.001    0.000    5.543    0.004 contextlib.py:108(__enter__)
     1246    0.000    0.000    5.543    0.004 {built-in method builtins.next}
     1246    0.000    0.000    5.543    0.004 base.py:68(profile)
     1246    0.001    0.000    5.542    0.004 advanced.py:61(start)
     1246    5.542    0.004    5.542    0.004 {method 'enable' of '_lsprof.Profiler' objects}
     1246    0.003    0.000    0.045    0.000 utilities.py:65(_build_training_step_kwargs)
     1246    0.002    0.000    0.041    0.000 signature_utils.py:18(is_param_in_hook_signature)

I could not find much information elsewhere, the only bit related is this SO question which is not much helping as I never call nor import cProfile in my code.

Anyone had a similar issue before?

Just in case:

python=3.8.12
pytorch=1.10
pytorch-lightning=1.5.8

[Hamptonjc]

Experiencing this issue as well.

[Shreeyak]

Yes, I faced a similar issue when debugging. Considering that PL is enabling the Profiler and printing the results at the end, cProfile would be called somewhere under the hood. Why it's causing such large overhead, I don't know.
Weird thing is that I disabled profiling and experienced almost identical execution times as with profiler enabled. Not sure where to look from here.

[sakvaua]

Same here, any workaround?

[BraveDistribution]

Have any of you had any luck with a workaround?

[akihironitta]

Hi all, I believe that's totally expected as Trainer(profiler="advanced") uses cProfile under the hood, which is documented in https://pytorch-lightning.readthedocs.io/en/1.6.4/advanced/profiler.html#advanced-profiler.

you can use the AdvancedProfiler. This option uses Python’s cProfiler to provide an in-depth report of time spent within each function called in your code.

You can see the implementation here: https://github.com/Lightning-AI/lightning/blob/1c05a9e597a0eb8f0eaf7b3ce1fa0b27e82cb19f/src/pytorch_lightning/profilers/advanced.py

[BraveDistribution]

Maybe I am missing something, but the problem is that if we use advanced profiler, it does not report anything useful.

At least for my problem, 25 seconds and 22 seconds in two methods (other take < 1 s) are described as _{method 'enable' of 'lsprof.Profiler' objects}. So, my program is slow, and the profiler does not give me any hint.

I think that it might be masking the underneath problem.

[Pedrexus]

Any update on this problem? I am experiencing this too and it is hard to profile given 99% of the time is on this, but without the profiler I see the same time.

[DavideCatto]

Any update?

[msinanyildirim]

Any updates on this?