2. Post-processing profiling data

2. Post-processing profiling data#

This notebook is a tour of the analysis API: ProfilingResults and the MPIRegion / Region objects it hands out.

The one thing worth memorising: every duration and timestamp in this API is in seconds, converted from the nanoseconds stored on disk.

[1]:

import tempfile
import time
from pathlib import Path

from scope_profiler import ProfileManager, read_h5

WORKDIR = Path(tempfile.mkdtemp(prefix="scope-profiler-tutorial-"))
DATA_FILE = WORKDIR / "profiling_data.h5"

ProfileManager.setup(file_path=str(DATA_FILE))


@ProfileManager.profile("assemble")
def assemble(scale):
    time.sleep(0.004 * scale)


with ProfileManager.profile_region("setup"):
    time.sleep(0.02)

for step in range(5):
    with ProfileManager.profile_region("timestep"):
        assemble(scale=1 + step % 3)
        with ProfileManager.profile_region("solve"):
            time.sleep(0.003)

ProfileManager.finalize(verbose=False)
results = read_h5(DATA_FILE)
results

[1]:

<ProfilingResults 'profiling_data.h5': 4 region(s), 1 rank(s)>

ProfilingResults is a mapping of regions#

It behaves like an ordered mapping from region name to region, so the usual Python idioms work.

[2]:

print("regions:", results.region_names)
print("count:", len(results))
print("'solve' recorded?", "solve" in results)
print("ranks in file:", results.num_ranks)

for region in results:
    print(f"  {region.name:<10} {region.num_calls:>3} calls")

regions: ['assemble', 'setup', 'timestep', 'solve']
count: 4
'solve' recorded? True
ranks in file: 1
  assemble     5 calls
  setup        1 calls
  timestep     5 calls
  solve        5 calls

Asking for something that is not there tells you what is there:

[3]:

try:
    results["sovle"]  # typo
except KeyError as exc:
    print(exc)

"No region named 'sovle' in /tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5. Available regions: ['assemble', 'setup', 'timestep', 'solve']"

Two levels: MPIRegion and Region#

results["solve"] returns an ``MPIRegion`` — the region across every rank that recorded it. Indexing it by rank gives a ``Region``, the timings from that one rank.

For a serial run there is only rank 0, but the two levels are the same API you use for an MPI run.

[4]:

timestep = results["timestep"]

print("aggregated over ranks")
print("  ranks       :", timestep.ranks)
print("  num_calls   :", timestep.num_calls)
print("  total   [s] :", timestep.total_duration)
print("  average [s] :", timestep.average_duration)
print("  min/max [s] :", timestep.min_duration, timestep.max_duration)
print("  std     [s] :", timestep.std_duration)

rank0 = timestep[0]
print("\nrank 0 only")
print("  durations [s]:", rank0.durations)
print("  start times [s]:", rank0.start_times)
print("  summary:", rank0.get_summary())

aggregated over ranks
  ranks       : [0]
  num_calls   : 5
  total   [s] : 0.051781265
  average [s] : 0.010356253
  min/max [s] : 0.007145383 0.015165983
  std     [s] : 0.002995423968500419

rank 0 only
  durations [s]: [0.00716907 0.01115715 0.01516598 0.00714538 0.01114369]
  start times [s]: [156.88244556 156.88961753 156.90077737 156.91594628 156.92309456]
  summary: {'num_calls': 5, 'total_duration': 0.051781265, 'inclusive_duration': 0.051781265, 'exclusive_duration': 6.5455e-05, 'average_duration': 0.010356253, 'min_duration': 0.007145383, 'max_duration': 0.015165983, 'first_duration': 0.007169067, 'last_duration': 0.011143686, 'std_duration': 0.002995423968500419}

Per-rank breakdowns are available as dictionaries keyed by rank, which is where load imbalance shows up in an MPI run:

[5]:

print("calls per rank :", timestep.num_calls_per_rank())
print("total per rank :", timestep.total_durations())
print("avg per rank   :", timestep.average_durations())
print("max per rank   :", timestep.max_durations())

calls per rank : {0: 5}
total per rank : {0: 0.051781265}
avg per rank   : {0: 0.010356253}
max per rank   : {0: 0.015165983}

Summaries and DataFrames#

summary() returns one dict per region, aggregated over ranks. print_summary() formats the same data as a table.

[6]:

results.print_summary()

  ╭─────────────┬─────┬─────────────┬───────────╮
  │ region      │ n   │ total [s]   │ avg [s]   │
  ├─────────────┼─────┼─────────────┼───────────┤
  │ setup       │ 1   │ 2.0e-02     │ 2.0e-02   │
  │ timestep    │ 5   │ 5.2e-02     │ 1.0e-02   │
  │ └─ assemble │ 5   │ 3.6e-02     │ 7.3e-03   │
  │ └─ solve    │ 5   │ 1.5e-02     │ 3.1e-03   │
  │ TOTAL       │ 16  │ 1.2e-01     │           │
  ╰─────────────┴─────┴─────────────┴───────────╯

  ╭─ Info ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
  │ Summary: ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5 (1 rank)                                      │
  │                                                                                                                                       │
  │ Explore:                                                                                                                              │
  │   Inspect: scope-profiler inspect ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5                      │
  │   TUI:     scope-profiler tui ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5                          │
  │                                                                                                                                       │
  │ Visualize and export:                                                                                                                 │
  │   Plot:    scope-profiler plot default ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5 -o plots --show │
  │   Report:  scope-profiler report ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5 -o report.html        │
  │   Export:  scope-profiler export plot-data ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5 -o data     │
  │   Lines:   scope-profiler line-profile ../../../../../../../../tmp/scope-profiler-tutorial-aphmwbar/profiling_data.h5                 │
  │                                                                                                                                       │
  │ Compare runs:                                                                                                                         │
  │   Diff:    scope-profiler diff BASE.h5 CANDIDATE.h5                                                                                   │
  │   Check:   scope-profiler check BASE.h5 CANDIDATE.h5                                                                                  │
  │                                                                                                                                       │
  │ Durations are in seconds.                                                                                                             │
  │ Regions may nest, so the summed total can exceed the wall-clock time.                                                                 │
  ╰───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯


[7]:

for row in results.summary():
    print(row)

{'name': 'setup', 'num_ranks': 1, 'num_calls': 1, 'total_duration': 0.020079415, 'inclusive_duration': 0.020079415, 'exclusive_duration': 0.020079415, 'average_duration': 0.020079415, 'min_duration': 0.020079415, 'max_duration': 0.020079415, 'first_duration': 0.020079415, 'last_duration': 0.020079415, 'std_duration': 0.0, 'tags': (), 'p50_duration': 0.020079415, 'p95_duration': 0.020079415, 'p99_duration': 0.020079415, 'rank_imbalance': 0.0, 'rank_imbalance_pct': 0.0, 'p50': 0.020079415, 'p95': 0.020079415, 'p99': 0.020079415, 'imbalance': 0.0}
{'name': 'timestep', 'num_ranks': 1, 'num_calls': 5, 'total_duration': 0.051781265, 'inclusive_duration': 0.051781265, 'exclusive_duration': 6.5455e-05, 'average_duration': 0.010356253, 'min_duration': 0.007145383, 'max_duration': 0.015165983, 'first_duration': 0.007169067, 'last_duration': 0.011143686, 'std_duration': 0.002995423968500419, 'tags': (), 'p50_duration': 0.011143686, 'p95_duration': 0.014364215599999999, 'p99_duration': 0.01500562952, 'rank_imbalance': 0.0, 'rank_imbalance_pct': 0.0, 'p50': 0.011143686, 'p95': 0.014364215599999999, 'p99': 0.01500562952, 'imbalance': 0.0}
{'name': 'assemble', 'num_ranks': 1, 'num_calls': 5, 'total_duration': 0.036365912, 'inclusive_duration': 0.036365912, 'exclusive_duration': 0.036365912, 'average_duration': 0.0072731824, 'min_duration': 0.004069909, 'max_duration': 0.012082558, 'first_duration': 0.00407022, 'last_duration': 0.008068723, 'std_duration': 0.002997499632040985, 'tags': (), 'p50_duration': 0.008068723, 'p95_duration': 0.0112809468, 'p99_duration': 0.01192223576, 'rank_imbalance': 0.0, 'rank_imbalance_pct': 0.0, 'p50': 0.008068723, 'p95': 0.0112809468, 'p99': 0.01192223576, 'imbalance': 0.0}
{'name': 'solve', 'num_ranks': 1, 'num_calls': 5, 'total_duration': 0.015349898, 'inclusive_duration': 0.015349898, 'exclusive_duration': 0.015349898, 'average_duration': 0.0030699796000000002, 'min_duration': 0.00306586, 'max_duration': 0.003074542, 'first_duration': 0.003074542, 'last_duration': 0.003066681, 'std_duration': 3.514645393208247e-06, 'tags': (), 'p50_duration': 0.003069284, 'p95_duration': 0.0030743398, 'p99_duration': 0.00307450156, 'rank_imbalance': 0.0, 'rank_imbalance_pct': 0.0, 'p50': 0.003069284, 'p95': 0.0030743398, 'p99': 0.00307450156, 'imbalance': 0.0}

With pandas installed (it comes with the plot extra), to_dataframe() gives you the same data ready for sorting, filtering and plotting.

[8]:

frame = results.to_dataframe()
frame.sort_values("total_duration", ascending=False)

[8]:
name num_ranks num_calls total_duration inclusive_duration exclusive_duration average_duration min_duration max_duration first_duration ... tags p50_duration p95_duration p99_duration rank_imbalance rank_imbalance_pct p50 p95 p99 imbalance
1 timestep 1 5 0.051781 0.051781 0.000065 0.010356 0.007145 0.015166 0.007169 ... () 0.011144 0.014364 0.015006 0.0 0.0 0.011144 0.014364 0.015006 0.0
2 assemble 1 5 0.036366 0.036366 0.036366 0.007273 0.004070 0.012083 0.004070 ... () 0.008069 0.011281 0.011922 0.0 0.0 0.008069 0.011281 0.011922 0.0
0 setup 1 1 0.020079 0.020079 0.020079 0.020079 0.020079 0.020079 0.020079 ... () 0.020079 0.020079 0.020079 0.0 0.0 0.020079 0.020079 0.020079 0.0
3 solve 1 5 0.015350 0.015350 0.015350 0.003070 0.003066 0.003075 0.003075 ... () 0.003069 0.003074 0.003075 0.0 0.0 0.003069 0.003074 0.003075 0.0

4 rows × 22 columns

per_rank=True emits one row per (region, rank) instead — the shape you want for load-balance analysis.

[9]:

results.to_dataframe(per_rank=True)

[9]:
name rank num_calls total_duration inclusive_duration exclusive_duration average_duration min_duration max_duration first_duration last_duration std_duration p50_duration p95_duration p99_duration
0 setup 0 1 0.020079 0.020079 0.020079 0.020079 0.020079 0.020079 0.020079 0.020079 0.000000 0.020079 0.020079 0.020079
1 timestep 0 5 0.051781 0.051781 0.000065 0.010356 0.007145 0.015166 0.007169 0.011144 0.002995 0.011144 0.014364 0.015006
2 assemble 0 5 0.036366 0.036366 0.036366 0.007273 0.004070 0.012083 0.004070 0.008069 0.002997 0.008069 0.011281 0.011922
3 solve 0 5 0.015350 0.015350 0.015350 0.003070 0.003066 0.003075 0.003075 0.003067 0.000004 0.003069 0.003074 0.003075 
[10]:

# Share of total recorded time per region.
frame = frame.assign(share=lambda df: df.total_duration / df.total_duration.sum())
frame[["name", "num_calls", "total_duration", "share"]].sort_values(
    "share", ascending=False
)

[10]:
name num_calls total_duration share
1 timestep 5 0.051781 0.419022
2 assemble 5 0.036366 0.294279
0 setup 1 0.020079 0.162486
3 solve 5 0.015350 0.124214

Selecting regions#

get_regions(), summary(), to_dataframe() and the plotting functions all take include / exclude, which are regular expressions matched against the region name (via re.match, so they anchor at the start).

[11]:

print([region.name for region in results.get_regions(include="s")])
print([region.name for region in results.get_regions(exclude=["setup", "assemble"])])
print([row["name"] for row in results.summary(include=["solve", "timestep"])])

['setup', 'solve']
['timestep', 'solve']
['timestep', 'solve']

Run metadata#

Each file carries the environment it was recorded in: the host and CPU, the loaded environment modules, the Slurm job it ran under, and selected environment variables such as PATH and VIRTUAL_ENV. This is what tells two otherwise identical runs apart months later.

[12]:

for key, value in sorted(results.metadata.items()):
    # PATH and friends run to thousands of characters; clip them for display.
    text = str(value)
    if len(text) > 70:
        text = text[:70] + " […]"
    print(f"{key:>24}: {text}")

         LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.10.21/x64/lib
                    PATH: /opt/hostedtoolcache/Python/3.10.21/x64/bin:/opt/hostedtoolcache/Pytho […]
        chip_information: AMD EPYC 9V74 80-Core Processor
        finalize_time_ns: 156934348692
                hostname: runnervmgx7h7
                 modules: []
                mpi_size: 1
         omp_num_threads: 4
                platform: Linux-6.17.0-1022-azure-x86_64-with-glibc2.39
          python_version: 3.10.21
  scope_profiler_version: 0.5.0
           start_time_ns: 156860262960
               timestamp: 2026-09-01T07:52:04.381792+00:00
             total_cores: 4
                   uname: Linux runnervmgx7h7 6.17.0-1022-azure #22-Ubuntu SMP Mon Jul 27 17:24: […]
                    user: runner
       working_directory: /home/runner/work/scope-profiler/scope-profiler/docs/source/tutorials

scope-profiler inspect prints the same metadata grouped and readable — together with per-region statistics — straight from the command line:

scope-profiler inspect profiling_data.h5
scope-profiler inspect profiling_data.h5 --metadata-only

write_metadata_json() exports it instead, with one entry per file and no clipping of long values:

[13]:

from scope_profiler.inspection import write_metadata_json

payload = write_metadata_json(DATA_FILE, WORKDIR / "metadata.json")
print(sorted(payload["files"][0]["metadata"])[:8])

['LD_LIBRARY_PATH', 'PATH', 'chip_information', 'finalize_time_ns', 'hostname', 'modules', 'mpi_size', 'omp_num_threads']

Exporting statistics#

collect_region_statistics() builds a JSON-ready dict (durations in seconds, with a units field spelling that out), and write_region_statistics_json() writes it to a file. Both accept several runs at once for run comparisons.

[14]:

from scope_profiler import collect_region_statistics, write_region_statistics_json

stats = collect_region_statistics(results, include="solve")
print(stats["units"])
print(stats["files"][0]["region_statistics"]["solve"])

stats_path = WORKDIR / "region_statistics.json"
write_region_statistics_json(results, stats_path)
print("wrote", stats_path)

{'durations': 'seconds'}
{'count': 5, 'average_duration_seconds': 0.0030699796000000002, 'min_duration_seconds': 0.00306586, 'max_duration_seconds': 0.003074542, 'first_duration_seconds': 0.003074542, 'last_duration_seconds': 0.003066681, 'std_duration_seconds': 3.514645393208247e-06, 'total_duration_seconds': 0.015349898, 'per_rank': {'0': {'count': 5, 'average_duration_seconds': 0.0030699796000000002, 'min_duration_seconds': 0.00306586, 'max_duration_seconds': 0.003074542, 'first_duration_seconds': 0.003074542, 'last_duration_seconds': 0.003066681, 'std_duration_seconds': 3.514645393208247e-06, 'total_duration_seconds': 0.015349898}}}
wrote /tmp/scope-profiler-tutorial-aphmwbar/region_statistics.json

Next#

3. Visualizing results turns these numbers into Gantt, flame and duration charts, and 5. Custom analysis goes below the summaries to the individual calls.

Contents