Skip to content

Commit 3eee8f1

Browse files
rohitgr7rohitgr7
authored
Sort simple profiler summary based on mean duration (#11671)
1 parent 7617521 commit 3eee8f1

File tree

4 files changed

+56
-41
lines changed

4 files changed

+56
-41
lines changed

‎CHANGELOG.md‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -222,6 +222,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/).
222222
- Changed `MisconfigurationException` to `ModuleNotFoundError` when `rich` isn't available ([#11360](https://github.com/PyTorchLightning/pytorch-lightning/pull/11360))
223223

224224

225+
- Sorted `SimpleProfiler(extended=False)` summary based on mean duration for each hook ([#11671](https://github.com/PyTorchLightning/pytorch-lightning/pull/11671))
226+
227+
225228
### Deprecated
226229

227230
- Deprecated `ClusterEnvironment.master_{address,port}` in favor of `ClusterEnvironment.main_{address,port}` ([#10103](https://github.com/PyTorchLightning/pytorch-lightning/pull/10103))

‎docs/source/advanced/profiler.rst‎

Lines changed: 15 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -63,23 +63,21 @@ The profiler's results will be printed at the completion of a training ``trainer
6363
-----------------------------------------------------------------------------------------------
6464
| Action | Mean duration (s) | Total time (s) |
6565
-----------------------------------------------------------------------------------------------
66-
| [LightningModule]BoringModel.prepare_data | 2.112e-06 | 2.112e-06 |
67-
| [LightningModule]BoringModel.setup | 1.513e-06 | 1.513e-06 |
68-
| [LightningModule]BoringModel.on_fit_start | 1.542e-06 | 1.542e-06 |
69-
| [LightningModule]BoringModel.on_epoch_start | 1.051e-06 | 1.051e-06 |
70-
| fetch_next_train_batch | 0.0003097 | 0.00061939 |
71-
| get_train_batch | 0.0003287 | 0.00065739 |
72-
| on_train_batch_start | 7.578e-05 | 7.578e-05 |
73-
| [LightningModule]BoringModel.training_step_end | 1.556e-06 | 1.556e-06 |
74-
| model_forward | 0.00028337 | 0.00028337 |
75-
| [LightningModule]BoringModel.optimizer_step | 0.0011853 | 0.0011853 |
76-
| run_training_batch | 0.0016311 | 0.0016311 |
77-
| on_train_batch_end | 7.6117e-05 | 7.6117e-05 |
78-
| run_training_epoch | 0.0036915 | 0.0036915 |
79-
| [LightningModule]BoringModel.on_epoch_end | 1.079e-06 | 1.079e-06 |
80-
| [LightningModule]BoringModel.on_train_end | 1.509e-06 | 1.509e-06 |
81-
| [LightningModule]BoringModel.on_fit_end | 3.127e-06 | 3.127e-06 |
82-
| [LightningModule]BoringModel.teardown | 2.581e-06 | 2.581e-06 |
66+
| run_training_epoch | 6.1558 | 6.1558 |
67+
| run_training_batch | 0.0022506 | 0.015754 |
68+
| [LightningModule]BoringModel.optimizer_step | 0.0017477 | 0.012234 |
69+
| model_forward | 0.00055868 | 0.0039108 |
70+
| [LightningModule]BoringModel.val_dataloader | 0.00024388 | 0.00024388 |
71+
| on_train_batch_start | 0.00014637 | 0.0010246 |
72+
| [LightningModule]BoringModel.teardown | 2.15e-06 | 2.15e-06 |
73+
| [LightningModule]BoringModel.prepare_data | 1.955e-06 | 1.955e-06 |
74+
| [LightningModule]BoringModel.on_epoch_end | 1.8373e-06 | 5.512e-06 |
75+
| [LightningModule]BoringModel.on_train_start | 1.644e-06 | 1.644e-06 |
76+
| [LightningModule]BoringModel.on_train_end | 1.516e-06 | 1.516e-06 |
77+
| [LightningModule]BoringModel.on_fit_end | 1.426e-06 | 1.426e-06 |
78+
| [LightningModule]BoringModel.setup | 1.403e-06 | 1.403e-06 |
79+
| [LightningModule]BoringModel.on_epoch_start | 1.2883e-06 | 3.865e-06 |
80+
| [LightningModule]BoringModel.on_fit_start | 1.226e-06 | 1.226e-06 |
8381
-----------------------------------------------------------------------------------------------
8482
8583
.. note:: Note that there are a lot more actions that will be present in the final report along with percentage and call count for each action.

‎pytorch_lightning/profiler/simple.py‎

Lines changed: 26 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -17,14 +17,19 @@
1717
import time
1818
from collections import defaultdict
1919
from pathlib import Path
20-
from typing import Dict, Optional, Tuple, Union
20+
from typing import Dict, List, Optional, Tuple, Union
2121

2222
import numpy as np
2323

2424
from pytorch_lightning.profiler.base import BaseProfiler
2525

2626
log = logging.getLogger(__name__)
2727

28+
_TABLE_ROW_EXTENDED = Tuple[str, float, int, float, float]
29+
_TABLE_DATA_EXTENDED = List[_TABLE_ROW_EXTENDED]
30+
_TABLE_ROW = Tuple[str, float, float]
31+
_TABLE_DATA = List[_TABLE_ROW]
32+
2833

2934
class SimpleProfiler(BaseProfiler):
3035
"""This profiler simply records the duration of actions (in seconds) and reports the mean duration of each
@@ -72,13 +77,21 @@ def stop(self, action_name: str) -> None:
7277
duration = end_time - start_time
7378
self.recorded_durations[action_name].append(duration)
7479

75-
def _make_report(self) -> Tuple[list, float]:
80+
def _make_report_extended(self) -> Tuple[_TABLE_DATA_EXTENDED, float, float]:
7681
total_duration = time.monotonic() - self.start_time
77-
report = [[a, d, 100.0 * np.sum(d) / total_duration] for a, d in self.recorded_durations.items()]
78-
report.sort(key=lambda x: x[2], reverse=True)
79-
total_calls = sum(len(x[1]) for x in report)
82+
report = [
83+
(a, np.mean(d), len(d), np.sum(d), 100.0 * np.sum(d) / total_duration)
84+
for a, d in self.recorded_durations.items()
85+
]
86+
report.sort(key=lambda x: x[4], reverse=True)
87+
total_calls = sum(x[2] for x in report)
8088
return report, total_calls, total_duration
8189

90+
def _make_report(self) -> _TABLE_DATA:
91+
report = [(action, np.mean(d), np.sum(d)) for action, d in self.recorded_durations.items()]
92+
report.sort(key=lambda x: x[1], reverse=True)
93+
return report
94+
8295
def summary(self) -> str:
8396
sep = os.linesep
8497
output_string = ""
@@ -100,15 +113,15 @@ def log_row(action, mean, num_calls, total, per):
100113
output_string_len = len(header_string.expandtabs())
101114
sep_lines = f"{sep}{'-' * output_string_len}"
102115
output_string += sep_lines + header_string + sep_lines
103-
report, total_calls, total_duration = self._make_report()
116+
report, total_calls, total_duration = self._make_report_extended()
104117
output_string += log_row("Total", "-", f"{total_calls:}", f"{total_duration:.5}", "100 %")
105118
output_string += sep_lines
106-
for action, durations, duration_per in report:
119+
for action, mean_duration, num_calls, total_duration, duration_per in report:
107120
output_string += log_row(
108121
action,
109-
f"{np.mean(durations):.5}",
110-
f"{len(durations):}",
111-
f"{np.sum(durations):.5}",
122+
f"{mean_duration:.5}",
123+
f"{num_calls}",
124+
f"{total_duration:.5}",
112125
f"{duration_per:.5}",
113126
)
114127
output_string += sep_lines
@@ -122,9 +135,10 @@ def log_row(action, mean, total):
122135
output_string_len = len(header_string.expandtabs())
123136
sep_lines = f"{sep}{'-' * output_string_len}"
124137
output_string += sep_lines + header_string + sep_lines
138+
report = self._make_report()
125139

126-
for action, durations in self.recorded_durations.items():
127-
output_string += log_row(action, f"{np.mean(durations):.5}", f"{np.sum(durations):.5}")
140+
for action, mean_duration, total_duration in report:
141+
output_string += log_row(action, f"{mean_duration:.5}", f"{total_duration:.5}")
128142
output_string += sep_lines
129143
output_string += sep
130144
return output_string

‎tests/profiler/test_profiler.py‎

Lines changed: 12 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -218,11 +218,11 @@ def test_simple_profiler_summary(tmpdir, extended):
218218
sep = os.linesep
219219
max_action_len = len("on_before_batch_transfer")
220220

221-
for hook in hooks:
221+
for i, hook in enumerate(hooks):
222222
with profiler.profile(hook):
223223
pass
224224

225-
profiler.recorded_durations[hook] = [sometime]
225+
profiler.recorded_durations[hook] = [sometime + i]
226226

227227
if extended:
228228
header_string = (
@@ -238,12 +238,12 @@ def test_simple_profiler_summary(tmpdir, extended):
238238
f"{sep_lines}"
239239
f"{sep}| Total | - | 6 | 7.0 | 100 % |" # noqa: E501
240240
f"{sep_lines}"
241+
f"{sep}| on_fit_start | 5.7734 | 1 | 5.7734 | 82.478 |" # noqa: E501
242+
f"{sep}| on_before_batch_transfer | 4.7734 | 1 | 4.7734 | 68.192 |" # noqa: E501
243+
f"{sep}| on_train_epoch_end | 3.7734 | 1 | 3.7734 | 53.906 |" # noqa: E501
244+
f"{sep}| on_train_epoch_start | 2.7734 | 1 | 2.7734 | 39.62 |" # noqa: E501
245+
f"{sep}| on_train_end | 1.7734 | 1 | 1.7734 | 25.335 |" # noqa: E501
241246
f"{sep}| on_train_start | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
242-
f"{sep}| on_train_end | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
243-
f"{sep}| on_train_epoch_start | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
244-
f"{sep}| on_train_epoch_end | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
245-
f"{sep}| on_before_batch_transfer | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
246-
f"{sep}| on_fit_start | 0.77343 | 1 | 0.77343 | 11.049 |" # noqa: E501
247247
f"{sep_lines}{sep}"
248248
)
249249
else:
@@ -257,12 +257,12 @@ def test_simple_profiler_summary(tmpdir, extended):
257257
f"{sep_lines}"
258258
f"{sep}| Action | Mean duration (s) | Total time (s) |"
259259
f"{sep_lines}"
260+
f"{sep}| on_fit_start | 5.7734 | 5.7734 |"
261+
f"{sep}| on_before_batch_transfer | 4.7734 | 4.7734 |"
262+
f"{sep}| on_train_epoch_end | 3.7734 | 3.7734 |"
263+
f"{sep}| on_train_epoch_start | 2.7734 | 2.7734 |"
264+
f"{sep}| on_train_end | 1.7734 | 1.7734 |"
260265
f"{sep}| on_train_start | 0.77343 | 0.77343 |"
261-
f"{sep}| on_train_end | 0.77343 | 0.77343 |"
262-
f"{sep}| on_train_epoch_start | 0.77343 | 0.77343 |"
263-
f"{sep}| on_train_epoch_end | 0.77343 | 0.77343 |"
264-
f"{sep}| on_before_batch_transfer | 0.77343 | 0.77343 |"
265-
f"{sep}| on_fit_start | 0.77343 | 0.77343 |"
266266
f"{sep_lines}{sep}"
267267
)
268268

0 commit comments

Comments
 (0)