tqdm progress bar in v1.6 is slower than v1.5

[akihironitta]

🐛 Bug

Training the boring model is slow with 1.6.0 (and master) compared to 1.5.10 with tqdm progress bar enabled.

time: 9.177419368177652  # 1.5.10
time: 12.62373811379075  # 1.6.0

To Reproduce

from time import monotonic
from pytorch_lightning import Trainer
from tests.helpers import BoringModel

def main():
    model = BoringModel()
    trainer = Trainer(
        max_epochs=100,
        enable_model_summary=False,
        enable_checkpointing=False,
        logger=False,
        # profiler="advanced",
    )
    t0 = monotonic()
    trainer.fit(model)
    print("time:", monotonic() - t0)

if __name__ == "__main__":
    main()

Expected behavior

No regression in speed.

Environment

• PyTorch Lightning Version (e.g., 1.5.0): 1.5.10 vs. 1.6.0
• PyTorch Version (e.g., 1.10): 1.11.0 and 1.8.2
• Python version (e.g., 3.9): 3.9
• OS (e.g., Linux): Linux
• CUDA/cuDNN version:
• GPU models and configuration:
• How you installed PyTorch (conda, pip, source):
• If compiling from source, the output of torch.__config__.show():
• Any other relevant information:

Additional context

The following benchmark result suggests that 8a549a5 (#11213) made the above code somewhat slow. Profiling the above script makes me think that the cause of the slowness is that #11213 added the expensive bar.refresh() call which still exists in master here:
https://github.com/PyTorchLightning/pytorch-lightning/blob/a6e9bc2943bf2c82036e31a4948bd8caa54957ee/pytorch_lightning/callbacks/progress/tqdm_progress.py#L390
benchmark result: https://www.akihironitta.com/lightning-benchmarks/#bench_fit.AnotherBoringBenchmark.time_it?branch=master&branch=release%2F1.5.x&pytorch=1.11&pytorch=1.8.2&torchvision=&pip%2Bprotobuf=3.20.1

---

Update: Just uncommented the refresh() call in https://github.com/PyTorchLightning/pytorch-lightning/tree/perf-tqdm and confirmed that it improves the performance to around the level of 1.5.10.

---

However, I'm not sure if we really need to fix this because:

• users will disable the progress bar anyway when they need maximum performance, and they'll see progress via their logger usually
• (and bar.refresh() makes the progress bar look smoother.)

cc @tchaton @rohitgr7 @awaelchli @Borda @akihironitta

[carmocca]

What is the runtime when rich is used instead?

Also, can you count the number of refresh calls with each version?

[akihironitta]

Here’s the result from the following script with max_epochs=1000.

Run this script

# Apply the patch when measuring with rich
from time import monotonic
from pytorch_lightning import Trainer
+from pytorch_lightning.callbacks import RichProgressBar
from tests.helpers import BoringModel


def main():
    model = BoringModel()
    trainer = Trainer(
        max_epochs=1000,
        enable_model_summary=False,
        enable_checkpointing=False,
        logger=False,
+        callbacks=RichProgressBar(),
    )
    t0 = monotonic()
    trainer.fit(model)
    print("time:", monotonic() - t0)


if __name__ == "__main__":
    main()

version	tqdm	rich
1.5.10	88.84	87.10
1.6.0	118.52	528.69
master	107.86	519.56
perf-tqdm	82.57	n/a

Haven't looked into why rich progress bar slows down significantly from 1.5.10 to 1.6.0 but will follow up.

---

Here's the number of refresh calls.

Run this command

The same script but with max_epochs=1.

$ for i in "1.5.10" "1.6.0" "master" "perf-tqdm"; do git checkout $i; python -m cProfile main.py 2> /dev/null |grep refresh; done

version	tqdm
1.5.10	75
1.6.0	267
master	271
perf-tqdm	77

[awaelchli]

Let's remove the refresh and rely on the previous implementation?
Maybe a test that counts the refresh calls could be useful for the future.

[akihironitta]

@awaelchli Thank you for your suggestion! While it sounds reasonable, I'm slightly in favor of doing nothing here because:

1. it is a tiny fraction of time compared to the whole execution time,
2. users will disable the progress bar anyway when they really care about performance, and
3. removing the refresh call reduces smoothness of the progress bar (as I checked in my branch https://github.com/Lightning-AI/lightning/tree/perf-tqdm).

(However, at the same time, I do also think we should fix this by removing the refresh since this "bug" affects quite a lot of users.)

[awaelchli]

removing the refresh call reduces smoothness of the progress bar (as I checked in my branch

I tried to verify this earlier but could not find any noticable difference. The refresh rate should be controlled by our parameter refresh_rate and not do more refreshes than requested. So I don't understand what this refresh call does. Do you have any additional insight here?

[awaelchli]

it is a tiny fraction of time compared to the whole execution time,

How small is tiny? Given your numbers here

time: 9.177419368177652 # 1.5.10
time: 12.62373811379075 # 1.6.0

12.62 - 9.17 = 3.45
3.45 / 9.17 = 0.376

This is 37% slower! Or in other words slower by a factor of 9.17 / 12.62 = 0.72

Our current GPU CI runs for roughly 1 hour (it is actually insane!!!).
The upper bound on savings here would be 60 * 0.72 = 16.9 minutes.

I would argue this is not bad considering that our testing relies so heavily on training boring models. This is why I see this as an opportunity worth investigating, as our CI runtime is embarrassingly and unreasonably long.

Btw, I was also wondering what exactly is going on here at the tail of your (awesome!!) benchmark plot for the 1.6.x versions.

[akihironitta]

I tried to verify this earlier but could not find any noticable difference

I've just tried to reproduce the difference which I saw a few weeks ago, but I haven't managed to do so... 😅 I can't remember how I checked the behaviour in the past, so I think we can go with your suggestion!

How small is tiny? ... our CI runtime is embarrassingly and unreasonably long.

I thought it was tiny because other factors (tensor operations, io, etc.) are more dominant by far usually, and a few seconds slowness for max_epochs=100 isn't the worst, but I see your point, and I'm now convinced that we should proceed forward with the fix given that our CI takes extremely long!

Btw, I was also wondering what exactly is going on here at the tail of your (awesome!!) benchmark plot for the 1.6.x versions.

To be honest, I'm not 100% sure, but I'm guessing that's nothing to do with changes in PL master. That's definitely in my TODO list and something that needs to be investigated. (Glad you had a chance to have a look at it :))

[awaelchli]

It looks like maybe it is not the progress bar refresh that is causing the slowdown. The CI does not seem to be affected. Compare
refresh removed
master

[carmocca]

Looking at the tqdm.update implementation, they have logic to automatically refresh the bar, so perhaps it is a good idea that we remove our manual refresh call.

https://github.com/tqdm/tqdm/blob/4f208e72552c4d916aa4fe6a955349ee8b2ed353/tqdm/std.py#L1256

[akihironitta]

Closing this since #13462 fixed this issue already. I'll create another issue for a possible regression in rich progress bar with a benchmark result across PL versions.