The code that migrated to pytorch lightning is very slow

[Keiku]

Below is the results when trained with 2 epochs, 500 videos for debugging. It's almost the same code, but the time per iter is quite different. How can I solve it?

Migrated PyTorch Lightning version

https://github.com/Keiku/PyTorch-Lightning-Video-Classification

The following is the execution result in the debug branch.

⋊> /m/n/k/c/PyTorch-Lightning-Video-Classification on main ⨯
pipenv run python train.py +experiments=train_exp01 hydra.run.dir=outputs/train_debug01
Global seed set to 0
GPU available: True, used: True
TPU available: False, using: 0 TPU cores
LOCAL_RANK: 0 - CUDA_VISIBLE_DEVICES: [0]
Global seed set to 0
Epoch 1: 100%|███████████████████| 62/62 [05:33<00:00,  5.38s/it, loss=4.59, v_num=0]
LOCAL_RANK: 0 - CUDA_VISIBLE_DEVICES: [0]
Testing: 100%|███████████████████████████████████████| 31/31 [02:24<00:00,  4.65s/it]
--------------------------------------------------------------------------------
DATALOADER:0 TEST RESULTS
{'acc/test': 0.04435483738780022}
--------------------------------------------------------------------------------
Elapsed time: 14.267 [min]
⋊> /m/n/k/c/PyTorch-Lightning-Video-Classification on main ⨯ 

PyTorch implementation before migration

https://github.com/Keiku/Action-Recognition-CNN-LSTM

⋊> /m/n/k/c/Action-Recognition-CNN-LSTM on main ⨯
pipenv run python train.py +experiments=train_exp02 hydra.run.dir=outputs/train_debug01
[2021-08-04 11:59:07,311][__main__][INFO] - Run script in outputs/train_debug01
[2021-08-04 11:59:14,036][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 1/32] [Loss: 4.615] [Acc: 0.000] [ETA: 0:01:06.491422] [Iter time: 1.039s/it]
[2021-08-04 11:59:14,311][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 2/32] [Loss: 4.615] [Acc: 0.000] [ETA: 0:00:17.294704] [Iter time: 0.275s/it]
[2021-08-04 11:59:14,587][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 3/32] [Loss: 4.616] [Acc: 0.000] [ETA: 0:00:17.116757] [Iter time: 0.276s/it]
[2021-08-04 11:59:14,867][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 4/32] [Loss: 4.615] [Acc: 0.000] [ETA: 0:00:17.080313] [Iter time: 0.28s/it]
[2021-08-04 11:59:15,147][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 5/32] [Loss: 4.615] [Acc: 0.000] [ETA: 0:00:16.840971] [Iter time: 0.281s/it]
[2021-08-04 11:59:15,429][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 6/32] [Loss: 4.615] [Acc: 0.010] [ETA: 0:00:16.608273] [Iter time: 0.282s/it]
[2021-08-04 11:59:15,709][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 7/32] [Loss: 4.615] [Acc: 0.009] [ETA: 0:00:16.259621] [Iter time: 0.28s/it]
[2021-08-04 11:59:15,986][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 8/32] [Loss: 4.615] [Acc: 0.016] [ETA: 0:00:15.794726] [Iter time: 0.277s/it]
[2021-08-04 11:59:16,265][__main__][INFO] - Training - [Epoch: 1/2] [Batch: 9/32] [Loss: 4.615] [Acc: 0.014] [ETA: 0:00:15.616598] [Iter time: 0.279s/it]

### omit ###

[2021-08-04 11:59:44,804][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 22/32] [Loss: 4.615] [Acc: 0.014] [ETA: 0:00:02.377135] [Iter time: 0.216s/it]
[2021-08-04 11:59:45,020][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 23/32] [Loss: 4.615] [Acc: 0.014] [ETA: 0:00:02.166957] [Iter time: 0.217s/it]
[2021-08-04 11:59:45,236][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 24/32] [Loss: 4.615] [Acc: 0.013] [ETA: 0:00:01.941448] [Iter time: 0.216s/it]
[2021-08-04 11:59:45,453][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 25/32] [Loss: 4.615] [Acc: 0.015] [ETA: 0:00:01.739038] [Iter time: 0.217s/it]
[2021-08-04 11:59:45,669][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 26/32] [Loss: 4.615] [Acc: 0.014] [ETA: 0:00:01.508613] [Iter time: 0.216s/it]
[2021-08-04 11:59:45,886][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 27/32] [Loss: 4.615] [Acc: 0.014] [ETA: 0:00:01.304092] [Iter time: 0.217s/it]
[2021-08-04 11:59:46,100][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 28/32] [Loss: 4.615] [Acc: 0.013] [ETA: 0:00:01.068049] [Iter time: 0.214s/it]
[2021-08-04 11:59:46,318][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 29/32] [Loss: 4.615] [Acc: 0.017] [ETA: 0:00:00.870102] [Iter time: 0.218s/it]
[2021-08-04 11:59:46,535][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 30/32] [Loss: 4.615] [Acc: 0.017] [ETA: 0:00:00.651664] [Iter time: 0.217s/it]
[2021-08-04 11:59:46,751][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 31/32] [Loss: 4.615] [Acc: 0.016] [ETA: 0:00:00.433284] [Iter time: 0.217s/it]
[2021-08-04 11:59:46,824][__main__][INFO] - Testing - [Epoch: 2/2] [Batch: 32/32] [Loss: 4.615] [Acc: 0.016] [ETA: 0:00:00.072523] [Iter time: 0.073s/it]
Elapsed time: 0.667 [min]
⋊> /m/n/k/c/Action-Recognition-CNN-LSTM on main ⨯ 

The iteration time is about 25 times different, and the total time is also about 25 times different.

Below is the result of profiler = "simple". Do you know what the problem is?

⋊> /m/n/k/c/PyTorch-Lightning-Video-Classification on main ⨯
pipenv run python train.py +experiments=train_exp01 hydra.run.dir=outputs/train_debug
02
Global seed set to 0
GPU available: True, used: True
TPU available: False, using: 0 TPU cores
LOCAL_RANK: 0 - CUDA_VISIBLE_DEVICES: [0]
Global seed set to 0
Epoch 1: 100%|███████████████████| 62/62 [05:28<00:00,  5.30s/it, loss=4.59, v_num=0]
FIT Profiler Report

Action                                  |  Mean duration (s)    |Num calls          |  Total time (s)        |  Percentage %         |
--------------------------------------------------------------------------------------------------------------------------------------
Total                                   |  -                    |_                  |  681.71                |  100 %                |
--------------------------------------------------------------------------------------------------------------------------------------
run_training_epoch                      |  327.85               |2                  |  655.71                |  96.186               |
run_training_batch                      |  4.8569               |62                 |  301.13                |  44.172               |
optimizer_step_and_closure_0            |  4.7922               |62                 |  297.12                |  43.584               |
training_step_and_backward              |  4.7876               |62                 |  296.83                |  43.542               |
model_forward                           |  4.7764               |62                 |  296.14                |  43.44                |
training_step                           |  4.7761               |62                 |  296.12                |  43.437               |
evaluation_step_and_end                 |  4.4423               |64                 |  284.31                |  41.705               |
validation_step                         |  4.442                |64                 |  284.29                |  41.702               |
on_validation_end                       |  16.583               |3                  |  49.748                |  7.2976               |
get_train_batch                         |  0.2741               |62                 |  16.994                |  2.4929               |
backward                                |  0.0099199            |62                 |  0.61503               |  0.090219             |
on_train_batch_end                      |  0.0022023            |62                 |  0.13654               |  0.020029             |
on_validation_batch_end                 |  0.00074679           |64                 |  0.047795              |  0.007011             |
on_train_start                          |  0.018023             |1                  |  0.018023              |  0.0026438            |
cache_result                            |  3.1013e-05           |474                |  0.0147                |  0.0021564            |
on_validation_batch_start               |  3.0629e-05           |64                 |  0.0019603             |  0.00028755           |
on_batch_start                          |  2.7673e-05           |62                 |  0.0017157             |  0.00025168           |
on_after_backward                       |  2.6987e-05           |62                 |  0.0016732             |  0.00024544           |
on_batch_end                            |  2.1419e-05           |62                 |  0.001328              |  0.0001948            |
validation_step_end                     |  2.0168e-05           |64                 |  0.0012907             |  0.00018934           |
on_before_zero_grad                     |  1.9801e-05           |62                 |  0.0012277             |  0.00018009           |
on_validation_start                     |  0.00036409           |3                  |  0.0010923             |  0.00016023           |
on_train_batch_start                    |  1.6072e-05           |62                 |  0.00099645            |  0.00014617           |
training_step_end                       |  1.5359e-05           |62                 |  0.00095228            |  0.00013969           |
on_train_epoch_start                    |  0.0004004            |2                  |  0.0008008             |  0.00011747           |
on_train_epoch_end                      |  0.00019737           |2                  |  0.00039474            |  5.7903e-05           |
on_train_end                            |  0.00030993           |1                  |  0.00030993            |  4.5463e-05           |
on_epoch_start                          |  1.4074e-05           |5                  |  7.0368e-05            |  1.0322e-05           |
on_validation_epoch_end                 |  2.2301e-05           |3                  |  6.6902e-05            |  9.8138e-06           |
on_epoch_end                            |  1.226e-05            |5                  |  6.1301e-05            |  8.9922e-06           |
on_validation_epoch_start               |  1.022e-05            |3                  |  3.066e-05             |  4.4975e-06           |
on_fit_start                            |  2.4181e-05           |1                  |  2.4181e-05            |  3.5471e-06           |
on_train_dataloader                     |  1.6511e-05           |1                  |  1.6511e-05            |  2.422e-06            |
on_before_accelerator_backend_setup     |  1.2315e-05           |1                  |  1.2315e-05            |  1.8065e-06           |
on_val_dataloader                       |  9.203e-06            |1                  |  9.203e-06             |  1.35e-06             |

LOCAL_RANK: 0 - CUDA_VISIBLE_DEVICES: [0]
Testing: 100%|███████████████████████████████████████| 31/31 [02:24<00:00,  4.66s/it]
TEST Profiler Report

Action                                  |  Mean duration (s)    |Num calls          |  Total time (s)        |  Percentage %         |
---------------------------------------------------------------------------------------------------------------------------------------
Total                                   |  -                    |_                  |  839.53                |  100 %                |
---------------------------------------------------------------------------------------------------------------------------------------
run_training_epoch                      |  327.85               |2                  |  655.71                |  78.105               |
evaluation_step_and_end                 |  4.4497               |95                 |  422.72                |  50.353               |
run_training_batch                      |  4.8569               |62                 |  301.13                |  35.869               |
optimizer_step_and_closure_0            |  4.7922               |62                 |  297.12                |  35.391               |
training_step_and_backward              |  4.7876               |62                 |  296.83                |  35.357               |
model_forward                           |  4.7764               |62                 |  296.14                |  35.274               |
training_step                           |  4.7761               |62                 |  296.12                |  35.272               |
validation_step                         |  4.442                |64                 |  284.29                |  33.863               |
test_step                               |  4.4649               |31                 |  138.41                |  16.487               |
on_validation_end                       |  16.583               |3                  |  49.748                |  5.9258               |
get_train_batch                         |  0.2741               |62                 |  16.994                |  2.0243               |
backward                                |  0.0099199            |62                 |  0.61503               |  0.073259             |
on_train_batch_end                      |  0.0022023            |62                 |  0.13654               |  0.016264             |
on_validation_batch_end                 |  0.00074679           |64                 |  0.047795              |  0.0056931            |
on_train_start                          |  0.018023             |1                  |  0.018023              |  0.0021468            |
cache_result                            |  3.1093e-05           |577                |  0.01794               |  0.002137             |
on_test_batch_end                       |  0.00044454           |31                 |  0.013781              |  0.0016415            |
on_validation_batch_start               |  3.0629e-05           |64                 |  0.0019603             |  0.0002335            |
on_batch_start                          |  2.7673e-05           |62                 |  0.0017157             |  0.00020437           |
on_after_backward                       |  2.6987e-05           |62                 |  0.0016732             |  0.0001993            |
on_batch_end                            |  2.1419e-05           |62                 |  0.001328              |  0.00015818           |
validation_step_end                     |  2.0168e-05           |64                 |  0.0012907             |  0.00015374           |
on_before_zero_grad                     |  1.9801e-05           |62                 |  0.0012277             |  0.00014624           |
on_validation_start                     |  0.00036409           |3                  |  0.0010923             |  0.00013011           |
on_train_batch_start                    |  1.6072e-05           |62                 |  0.00099645            |  0.00011869           |
training_step_end                       |  1.5359e-05           |62                 |  0.00095228            |  0.00011343           |
on_train_epoch_start                    |  0.0004004            |2                  |  0.0008008             |  9.5388e-05           |
on_test_batch_start                     |  2.5826e-05           |31                 |  0.0008006             |  9.5364e-05           |
test_step_end                           |  1.5975e-05           |31                 |  0.00049524            |  5.899e-05            |
on_train_epoch_end                      |  0.00019737           |2                  |  0.00039474            |  4.7019e-05           |
on_test_end                             |  0.00033481           |1                  |  0.00033481            |  3.988e-05            |
on_train_end                            |  0.00030993           |1                  |  0.00030993            |  3.6917e-05           |
on_test_start                           |  0.00029306           |1                  |  0.00029306            |  3.4907e-05           |
on_epoch_start                          |  1.3728e-05           |6                  |  8.2368e-05            |  9.8112e-06           |
on_epoch_end                            |  1.1922e-05           |6                  |  7.153e-05             |  8.5203e-06           |
on_validation_epoch_end                 |  2.2301e-05           |3                  |  6.6902e-05            |  7.969e-06            |
on_fit_end                              |  3.6485e-05           |1                  |  3.6485e-05            |  4.3459e-06           |
on_before_accelerator_backend_setup     |  1.7077e-05           |2                  |  3.4155e-05            |  4.0684e-06           |
on_validation_epoch_start               |  1.022e-05            |3                  |  3.066e-05             |  3.652e-06            |
on_fit_start                            |  2.4181e-05           |1                  |  2.4181e-05            |  2.8803e-06           |
on_test_epoch_end                       |  2.3251e-05           |1                  |  2.3251e-05            |  2.7695e-06           |
on_train_dataloader                     |  1.6511e-05           |1                  |  1.6511e-05            |  1.9667e-06           |
on_test_dataloader                      |  1.3014e-05           |1                  |  1.3014e-05            |  1.5502e-06           |
on_test_epoch_start                     |  1.0905e-05           |1                  |  1.0905e-05            |  1.2989e-06           |
on_val_dataloader                       |  9.203e-06            |1                  |  9.203e-06             |  1.0962e-06           |

--------------------------------------------------------------------------------
DATALOADER:0 TEST RESULTS
{'acc/test': 0.04435483738780022}
--------------------------------------------------------------------------------
Elapsed time: 14.009 [min]
⋊> /m/n/k/c/PyTorch-Lightning-Video-Classification on main ⨯ 

[TheMrZZ]

I have a very similar problem, and my profiling results look just like yours (see my issue here). Did you manage to solve the issue?

[Keiku]

I haven't solved it yet. This problem is difficult and left unattended. I don't know if it will work, but I'm thinking of upgrading to version 1.5. On the contrary, please let me know if you solve it.

[TheMrZZ]

Good to know. I'll get back to you if I find any solution. Are you running on Windows? I'm wondering if it's a OS-specific problem.

This entire issue still is weird, since it does not happen with vanilla Pytorch.

(btw, I'm already using the latest pytorch & lightning version, so that's not the root cause)

[Keiku]

I'm using Ubuntu 18.04. I don't think it's an OS issue. I have no idea.

[tchaton]

Dear @Keiku,

We will prioritize this higher to unblock you if possible.

Best,
T.C

[Keiku]

If I have time, I will prepare a dataset that can easily verify bugs.

[kaushikb11]

@Keiku Could you try the master? We have resolved some performance issues.

[Keiku]

Is it my PyTorch-Lightning-Video-Classification repo?

[kaushikb11]

No, the Pytorch lightning repo

[Keiku]

I haven't tried the latest version of pytorch-lighting yet. I will try it.