profiling lazy resampling and compose

[wyli]

When enabling lazy resampling for existing preprocessing pipelines, comparing breakdown time and memory cost is essential.

MONAI/monai/transforms/compose.py

Lines 188 to 203 in e18097d

	for _transform in transforms[start:end]:
	if threading:
	_transform = deepcopy(_transform) if isinstance(_transform, ThreadUnsafe) else _transform
	data = evaluate_with_overrides(
	data,
	_transform,
	lazy_evaluation=lazy_evaluation,
	overrides=overrides,
	override_keys=override_keys,
	verbose=verbose,
	)
	data = apply_transform(_transform, data, map_items, unpack_items, log_stats)
	data = evaluate_with_overrides(
	data, None, lazy_evaluation=lazy_evaluation, overrides=overrides, override_keys=override_keys, verbose=verbose
	)
	return data

it's possible to modify the compose function to estimate the time roughly:

diff --git a/monai/transforms/compose.py b/monai/transforms/compose.py
index 5266202c4..5a0e8ece6 100644
--- a/monai/transforms/compose.py
+++ b/monai/transforms/compose.py
@@ -184,10 +184,12 @@ def execute_compose(
     # no-op if the range is empty
     if start == end:
         return data

+    import time
+    a = time.time()
     for _transform in transforms[start:end]:
         if threading:
             _transform = deepcopy(_transform) if isinstance(_transform, ThreadUnsafe) else _transform
+        s = time.time()
         data = evaluate_with_overrides(
             data,
             _transform,
@@ -197,9 +199,11 @@ def execute_compose(
             verbose=verbose,
         )
         data = apply_transform(_transform, data, map_items, unpack_items, log_stats)
+        print(f"transform {_transform.__class__.__name__}", time.time() - s)
     data = evaluate_with_overrides(
         data, None, lazy_evaluation=lazy_evaluation, overrides=overrides, override_keys=override_keys, verbose=verbose
     )
+    print("total time", time.time() - a)
     return data

or use from monai.utils.nvtx import Range (e.g. https://github.com/Project-MONAI/tutorials/blob/main/acceleration/fast_training_tutorial.ipynb) which is primarily for benchmarking GPU operations.

would be great to have a recommended way to enable profiling easily, perhaps integrating some of the existing tools https://github.com/Project-MONAI/MONAI/blob/dev/monai/utils/profiling.py into Compose?
cc @atbenmurray @ericspod @Nic-Ma @KumoLiu @yiheng-wang-nv

[ericspod]

The WorkflowProfiler class is meant to be used to manually instrument a workflow during development and testing. It wasn't meant to be something easily enabled without code modifications. It relies on tracing to measure call times which is something we could use to patch into certain events in a transform pipeline but this has it's own overhead and complications. We could provide a function for the argument call_selector which selects when execute_composeis called and measure times for it.

[Zrrr1997]

Something similar to the code snippet by @wyli helped me identify many bottlenecks in my training workflow, so it is definitely worth adding as a flag to either the Compose transform or to the Transform class, e.g. log_time=True, which would simply measure the time before and after the apply_transform operation. It would be quite helpful albeit a bit naive and simple.

[wyli]

The workflow profiler also works well, it's quite convenient, please see https://github.com/Project-MONAI/tutorials/blob/main/modules/lazy_resampling_benchmark.ipynb