Line-by-line profiling#
scope-profiler can integrate line_profiler to give you per-source-line timing breakdowns of decorated functions, alongside the usual region-level statistics.
Installation#
pip install "scope-profiler[line-profiler]"
Enabling line profiling#
Pass use_line_profiler=True to setup():
from scope_profiler import ProfileManager
ProfileManager.setup(use_line_profiler=True)
This selects LineProfilerRegion for all regions. Each region records
nanosecond timestamps and enables line_profiler tracing for decorated
functions and for the function containing a with scope.
Example#
import math
import random
from scope_profiler import ProfileManager
ProfileManager.setup(use_line_profiler=True)
@ProfileManager.profile("compute")
def compute(N=50_000):
s = 0.0
for _ in range(N):
x = random.random()
s += math.sin(x) * math.sqrt(x + 1.0)
return s
@ProfileManager.profile("allocate")
def allocate(N=100_000):
a = [i * i for i in range(N)]
b = []
for i in range(N):
b.append(i * i)
return a, b
def run_scope_only():
with ProfileManager.profile_region("scope_only"):
total = sum(range(100_000))
return total
compute()
allocate()
run_scope_only()
ProfileManager.finalize()
Output:
╭────────────────────────┬─────┬─────────────┬─────────────┬───────────╮
│ region │ n │ % session │ total [s] │ avg [s] │
├────────────────────────┼─────┼─────────────┼─────────────┼───────────┤
│ scope_profiler.session │ 1 │ 100.00% │ 1.1e-01 │ 1.1e-01 │
│ └─ compute │ 1 │ 46.72% │ 4.9e-02 │ 4.9e-02 │
│ └─ allocate │ 1 │ 51.60% │ 5.4e-02 │ 5.4e-02 │
│ TOTAL │ 3 │ 100.00% │ 2.1e-01 │ │
╰────────────────────────┴─────┴─────────────┴─────────────┴───────────╯
╭─ Info ──────────────────────────────────────────────────────────────────────╮
│ Summary: profiling_data.h5 (1 rank) │
│ │
│ Explore: │
│ Inspect: scope-profiler inspect profiling_data.h5 │
│ TUI: scope-profiler tui profiling_data.h5 │
│ │
│ Visualize and export: │
│ Plot: scope-profiler plot default profiling_data.h5 -o plots --show │
│ Report: scope-profiler report profiling_data.h5 -o report.html │
│ Export: scope-profiler export plot-data profiling_data.h5 -o data │
│ Lines: scope-profiler line-profile 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. │
│ % session uses wall-clock coverage; overlapping recursive calls count once. │
╰─────────────────────────────────────────────────────────────────────────────╯
Timer unit: 1e-09 s
Total time: 0.0395527 s
File: examples/ex_line_profiling.py
Function: compute at line 42
Line # Hits Time Per Hit % Time Line Contents
==============================================================
42 @ProfileManager.profile("compute")
43 def compute(N=50_000):
44 """Some mixed math to illustrate per-line costs."""
45 1 441.0 441.0 0.0 s = 0.0
46 50001 7473489.0 149.5 18.9 for _ in range(N):
47 50000 10113307.0 202.3 25.6 x = random.random()
48 50000 21964818.0 439.3 55.5 s += math.sin(x) * math.sqrt(x + 1.0)
49 1 641.0 641.0 0.0 return s
Timer unit: 1e-09 s
Total time: 3.8e-07 s
File: /opt/hostedtoolcache/Python/3.10.21/x64/lib/python3.10/site-packages/scope_profiler/profile_manager.py
Function: __enter__ at line 148
Line # Hits Time Per Hit % Time Line Contents
==============================================================
148 def __enter__(self):
149 self._manager.setup(**self._setup_kwargs)
150 # Keep every region created in the session under one interval. Apart
151 # from making the total elapsed time explicit, this gives call-graph
152 # consumers a single root instead of a forest whose display order can
153 # be mistaken for execution order (notably by SnakeViz).
154 self._root_region = self._manager.profile_region(self.ROOT_REGION_NAME)
155 self._root_region.__enter__()
156 1 380.0 380.0 100.0 return self
Timer unit: 1e-09 s
Total time: 0.054267 s
File: examples/ex_line_profiling.py
Function: run_allocate at line 66
Line # Hits Time Per Hit % Time Line Contents
==============================================================
66 def run_allocate(N=100_000):
67 """The enclosing function is line-profiled automatically."""
68 with ProfileManager.profile_region("allocate"):
69 1 54267029.0 5.43e+07 100.0 return allocate(N)
70 print("print allocate")
The line-by-line table shows, for each source line:
Column |
Meaning |
|---|---|
Hits |
Number of times the line was executed |
Time |
Total time spent on that line (in timer units) |
Per Hit |
Average time per execution |
% Time |
Fraction of the function’s total time |
Decorator vs. context manager#
Decorator (
@ProfileManager.profile) — automatically registers the function withline_profiler. This is the primary use case.Context manager (
with ProfileManager.profile_region()) — enables/disables the profiler around the block and automatically registers the active caller function. Lines executed in the scope are included even when the function is not decorated. Passingfunctions=[...]remains useful when the scope should also profile other functions it calls.
Accessing stats programmatically#
region = ProfileManager.get_region("compute")
# Get the line_profiler stats object
stats = region.get_stats()
# Print formatted output
region.print_stats()
The generated example prints a standard line_profiler table:
Total time: 0.0395527 s
File: examples/ex_line_profiling.py
Function: compute at line 42
Line # Hits Time Per Hit % Time Line Contents
==============================================================
42 @ProfileManager.profile("compute")
43 def compute(N=50_000):
44 """Some mixed math to illustrate per-line costs."""
45 1 441.0 441.0 0.0 s = 0.0
46 50001 7473489.0 149.5 18.9 for _ in range(N):
47 50000 10113307.0 202.3 25.6 x = random.random()
48 50000 21964818.0 439.3 55.5 s += math.sin(x) * math.sqrt(x + 1.0)
49 1 641.0 641.0 0.0 return s
Line-profiler data is also persisted in the HDF5 output. After reopening
a run, access the rank-local records through
ProfilingResults.line_profile:
from scope_profiler import read_h5
results = read_h5("profiling_data.h5")
for record in results.line_profile.get(0, []):
seconds_per_unit = record["unit"]
for line, hits, elapsed in zip(
record["line_numbers"], record["hits"], record["times"]
):
print(record["function"], line, hits, elapsed * seconds_per_unit)
This prints the persisted records from the generated example:
compute 45 1 4.4100000000000004e-07
compute 46 50001 0.007473489000000001
compute 47 50000 0.010113307
compute 48 50000 0.021964818
compute 49 1 6.410000000000001e-07
__enter__ 156 1 3.8e-07
run_allocate 69 1 0.054267029
Each record is associated with its region, source file, and function.
The stored times values use the unit reported by line_profiler.
The same data can be printed from the command line:
scope-profiler line-profile profiling_data.h5
scope-profiler line-profile profiling_data.h5 --rank 0 --function compute
The filtered command produces:
Line profile: profiling_data.h5
Rank 0 | compute | compute (/home/runner/work/scope-profiler/scope-profiler/examples/ex_line_profiling.py:42)
╭────────┬────────┬────────────┬───────────────┬──────────┬───────────────────────────────────────────╮
│ line │ hits │ time [s] │ per hit [s] │ % time │ source │
├────────┼────────┼────────────┼───────────────┼──────────┼───────────────────────────────────────────┤
│ 45 │ 1 │ 4.41e-07 │ 4.41e-07 │ 0.00 │ s = 0.0 │
│ 46 │ 50001 │ 0.00747349 │ 1.49467e-07 │ 18.90 │ for _ in range(N): │
│ 47 │ 50000 │ 0.0101133 │ 2.02266e-07 │ 25.57 │ x = random.random() │
│ 48 │ 50000 │ 0.0219648 │ 4.39296e-07 │ 55.53 │ s += math.sin(x) * math.sqrt(x + 1.0) │
│ 49 │ 1 │ 6.41e-07 │ 6.41e-07 │ 0.00 │ return s │
╰────────┴────────┴────────────┴───────────────┴──────────┴───────────────────────────────────────────╯
Overhead considerations#
Line profiling adds ~40 µs per call because line_profiler instruments
every source line in the function. It is designed for targeted
debugging, not for always-on use in hot loops. See Profiling overhead for
benchmark data.