Skip to content

Commit 79609ea

Browse files
authored
Fix two more divide-by-zero bugs found by the formalization audit (#1078)
* Fix divide-by-zero in per-stack CPU normalization (--stacks + memory-only) The stacks-normalization loop in ScaleneJSON.output_profiles divided each recorded stack's timings by stats.cpu_stats.total_cpu_samples with no guard. That denominator can be 0.0 while stats.stacks is non-empty: a memory-only run with --stacks records stack entries (from the CPU sampler's stack collection) while it is *memory* activity -- not CPU activity -- that passes the 'nothing to output' gate at the top of output_profiles. With no CPU sample ever recorded, total_cpu_samples stays at its initial 0.0 and the loop raises ZeroDivisionError. The sibling per-file/per-line CPU normalizations (~556, ~1259, ~1337) already guard this; this site was missed. Same bug class as the leak-velocity divide (#1077). Found by re-running the formalization audit's 'every denominator is a claim to verify' sweep across the output path (formal/README.md 'Bugs the formalization found', now three). Guard the loop on total_cpu_samples (raw stack entries preserved when 0). Regression test drives the full output_profiles path, so it crashes pre-fix and passes after. * Fix CLI-renderer twin of the leak-velocity divide-by-zero Bug #1 (fixed in #1077) was an unguarded leak_velocity / stats.elapsed_time in the JSON renderer. Scalene has three separate output renderers (Scalene-Debugging.md); the CLI renderer scalene_output.py:699 (scalene view --cli) carried the identical unguarded divide, which #1077 did not touch. Same reachability as #1: compute_leaks gates on allocation growth rate, not wall-clock time, so a leak can be reported on a sub-millisecond run where elapsed_time is still 0.0 -> ZeroDivisionError. Found by re-running the denominator audit across the CLI output path (the other output.py divides at ~339/~379/~416/~657 are already guarded). Guard the velocity denominator, mirroring the #1077 json.py fix. Regression test added. Also updates formal/README.md + HANDOFF.md (now four bugs found). The takeaway, now recorded in HANDOFF: a fix in one renderer does not cover its siblings -- audit all three.
1 parent a14024b commit 79609ea

6 files changed

Lines changed: 294 additions & 25 deletions

File tree

formal/HANDOFF.md

Lines changed: 43 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ Working doc so this can be picked up after a context reset. Captures what the
44
formal-verification effort has produced, the *method* (including a hard-won
55
lesson), what's merged vs. open, and concrete next steps.
66

7-
Last updated: 2026-06-30.
7+
Last updated: 2026-07-01.
88

99
---
1010

@@ -16,7 +16,7 @@ reasons, in priority order:
1616
1. **Find and fix real bugs.** Formalizing forces every implicit assumption to
1717
be named. Where the code doesn't enforce what a proof needs, that's a
1818
finding — a real defect or an undocumented invariant. This has already paid
19-
off (two production bugs, see §4).
19+
off (four production bugs, see §4).
2020
2. **Establish correctness** of the properties a profiler's *user* relies on.
2121

2222
**THE METHODOLOGICAL LESSON (most important thing in this doc):** a proof whose
@@ -109,19 +109,23 @@ Formal + the CI/bug work that unblocked it:
109109
(Bool-param branch inversion; binary `min`/`max` operand drop) found while
110110
extracting Scalene's defs. Local checkout: `/tmp/LeanToPython`.
111111

112-
## 3b. OPEN PRs (need driving to merge)
112+
Also merged 2026-07-01:
113+
- **#1077** the two production bug fixes from §4 (leak-velocity div-by-zero +
114+
sampling-window clamp).
115+
- **#1076** two-counter bisimulation + per-line attribution +
116+
`LeakTrackerAudit.lean` + `LeakTrackerConcurrency.lean` (leak-tracker
117+
concurrency/fork gap) + README "bugs found".
113118

114-
- **#1077** `fix-leak-velocity-and-sampling-window` — the two production bug
115-
fixes from §4. Independent, mergeable now. (1 commit.)
116-
- **#1076** `formal-sampler-refinements` — two-counter bisimulation +
117-
per-line attribution + `LeakTrackerAudit.lean` + README "bugs found". (2
118-
commits.) Formal-only; CI failures on it are transient/flake (see §5).
119+
## 3b. OPEN PRs (need driving to merge)
119120

120-
Merge order suggestion: #1077 first (it's the real fix), then #1076.
121+
- **#1078** `fix-stacks-total-cpu-zerodiv` — §4 bugs #3 (unguarded per-stack
122+
CPU normalization divide) and #4 (CLI-renderer twin of the leak-velocity
123+
divide). Two code fixes + two regression tests + README notes. Independent,
124+
mergeable.
121125

122126
---
123127

124-
## 4. Bugs the formalization found (BOTH FIXED in #1077)
128+
## 4. Bugs the formalization found (#1, #2 FIXED in #1077; #3, #4 in #1078)
125129

126130
1. **ZeroDivisionError, leak velocity.** `scalene_json.py` ~line 1255:
127131
`"velocity_mb_s": leak_velocity / stats.elapsed_time` was unguarded.
@@ -136,7 +140,24 @@ Merge order suggestion: #1077 first (it's the real fix), then #1076.
136140
`MemorySampler.lean`). Fixed by clamping ≤0 to the default. Verified on
137141
cloudnew: `WINDOW=0` run now completes.
138142

139-
Third finding (no bug, but was implicit): the leak formula
143+
3. **ZeroDivisionError, per-stack CPU normalization.** `scalene_json.py`, the
144+
`stats.stacks` normalization loop dividing by `cpu_stats.total_cpu_samples`
145+
was unguarded. `total_cpu_samples` can be `0.0` while `stats.stacks` is
146+
non-empty — a **memory-only run with `--stacks`** records stack entries but
147+
never a CPU sample, and it is *memory* activity (not CPU) that passes the
148+
"nothing to output" gate. Sibling CPU normalizations (~556, ~1259, ~1337)
149+
were already guarded; this one was missed → crash. Same class as #1. Found
150+
by re-running the §0 "every denominator is a claim" audit across the output
151+
path. Fixed + regression test (`tests/test_stacks_zero_cpu_samples.py`,
152+
drives the full `output_profiles` path). PR **#1078**.
153+
4. **CLI-renderer twin of #1.** `scalene_output.py:699` (the `scalene view
154+
--cli` leak report) had the identical unguarded `leak[2] /
155+
stats.elapsed_time` that #1077 fixed only in `scalene_json.py`. Scalene has
156+
three separate renderers (Scalene-Debugging.md) — fixing one doesn't cover
157+
the others. Found by auditing the CLI path's divides. Fixed + regression
158+
test (`tests/test_cli_leak_velocity_zero_elapsed.py`). Also PR **#1078**.
159+
160+
Additional finding (no bug, but was implicit): the leak formula
140161
`1 − (frees+1)/(allocs−frees+2)` has NO denominator guard; safety rests on
141162
`frees ≤ allocs`, which is non-obvious (two separate increment sites,
142163
`scalene_memory_profiler.py:236` and `:401`). `LeakTrackerAudit.lean` now
@@ -193,7 +214,8 @@ generated `X | Y` unions need 3.10+).
193214

194215
## 7. Concrete next steps (roughly ranked)
195216

196-
1. **Merge #1077 then #1076** (drive CI; re-run flakes per §5).
217+
1. ~~Merge #1077 then #1076~~ **DONE** (2026-07-01). Now: drive **#1078**
218+
(bug #3 fix) to merge — independent, small; re-run any flakes per §5.
197219
2. ~~Audit `LeakTrackerAudit`'s faithfulness under concurrency/fork~~ **DONE**
198220
`LeakTrackerConcurrency.lean` models the sig-queue/main-thread interleaving
199221
and fork reset explicitly, proves the invariant survives every interleaving,
@@ -202,9 +224,15 @@ generated `X | Y` unions need 3.10+).
202224
join in the code) rather than derived from the queue's operational semantics
203225
— a TLA+ spec of `ScaleneSigQueue.run` could discharge that too.
204226
3. **Keep auditing hypotheses adversarially** (the §0 method): every `0 <`,
205-
every denominator, every counter that could underflow. The audit that found
206-
§4's bugs covered the main division sites; re-run it whenever a model gains
207-
a new hypothesis.
227+
every denominator, every counter that could underflow. This is paying off —
228+
re-running the sweep across the output path found bug #3 (§4) after #1077.
229+
Divide sites in `scalene_json.py` are now all guarded/try-excepted (audited
230+
2026-07-01: ~556, ~583, ~585, ~592, ~621/632/637, ~659, ~759, ~779 (fixed
231+
#3), ~1186, ~1259, ~1337 — all guarded). `scalene_output.py` (the CLI
232+
renderer) also audited 2026-07-01 — found bug #4 at :699 (now fixed); its
233+
other divides (~339, ~379, ~416, ~657) are guarded. NEXT untouched surfaces:
234+
the third renderer's path + `sparkline.py` / `runningstats.py` variance/stddev
235+
denominators. Lesson reinforced by #4: audit ALL THREE renderers, not one.
208236
4. **Formalize PASTA** (or at least a discrete-time analogue) to fully discharge
209237
the i.i.d.→trueFraction step instead of citing it.
210238
5. **Prove per-sample classifier accuracy** for the python/native split, or

formal/README.md

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,7 @@ standard axioms (`propext`, `Classical.choice`, `Quot.sound`).
5353
Formalizing forces every implicit assumption to be named, which surfaces places
5454
where the code doesn't enforce what a proof needs. Auditing the models'
5555
hypotheses against the code (see `lean/Scalene/LeakTrackerAudit.lean` and the
56-
audit notes below) turned up two real defects, both since fixed:
56+
audit notes below) turned up four real defects, all since fixed:
5757

5858
1. **Unguarded divide-by-zero in leak-velocity reporting**
5959
(`scalene_json.py`, the `velocity_mb_s: leak_velocity / stats.elapsed_time`
@@ -68,6 +68,24 @@ audit notes below) turned up two real defects, both since fixed:
6868
sampler trigger on *every* allocation — and violates the `interval > 0`
6969
precondition `MemorySampler.lean` proves necessary. Fixed by clamping to the
7070
default when ≤ 0.
71+
3. **Unguarded divide-by-zero in per-stack CPU normalization**
72+
(`scalene_json.py`, the `stats.stacks` normalization loop dividing by
73+
`stats.cpu_stats.total_cpu_samples`). Same class as #1, found by re-running
74+
the "every denominator is a claim to verify" audit across the output path:
75+
`total_cpu_samples` can be `0.0` while `stats.stacks` is non-empty — a
76+
**memory-only run with `--stacks`** records stack entries but never a CPU
77+
sample, and it is *memory* activity (not CPU) that passes the
78+
"nothing to output" gate. The sibling per-file/per-line CPU normalizations
79+
(`~556`, `~1259`, `~1337`) were already guarded; this one was missed → crash.
80+
Fixed + regression test (`tests/test_stacks_zero_cpu_samples.py`).
81+
4. **The CLI-renderer twin of #1.** Scalene has *three separate output
82+
renderers* (see `Scalene-Debugging.md`). The #1 fix touched only the JSON
83+
renderer; `scalene_output.py` (the `scalene view --cli` path) carried the
84+
identical unguarded `leak[2] / stats.elapsed_time` in its leak report — same
85+
reachability (`compute_leaks` gates on growth rate, not time). Found by
86+
re-running the audit across the CLI path. Fixed + regression test
87+
(`tests/test_cli_leak_velocity_zero_elapsed.py`). A reminder that a fix in
88+
one renderer does not cover its siblings.
7189

7290
Additionally, `LeakTrackerAudit.lean` discharges an *implicit* safety contract:
7391
the leak formula `1 − (frees+1)/(allocs−frees+2)` has **no** guard on its

scalene/scalene_json.py

Lines changed: 17 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -772,14 +772,23 @@ def output_profiles(
772772
# Snapshot the keys first: stats.stacks is mutated from the CPU
773773
# sampling signal handler, so iterating the live view risks a
774774
# "dictionary changed size during iteration" RuntimeError.
775-
for stk in list(stats.stacks):
776-
stack_stats = stats.stacks[stk]
777-
stats.stacks[stk] = StackStats(
778-
stack_stats.count,
779-
stack_stats.python_time / stats.cpu_stats.total_cpu_samples,
780-
stack_stats.c_time / stats.cpu_stats.total_cpu_samples,
781-
stack_stats.cpu_samples / stats.cpu_stats.total_cpu_samples,
782-
)
775+
#
776+
# Guard the denominator: total_cpu_samples can be 0 while stats.stacks
777+
# is non-empty — e.g. a memory-only run with --stacks (memory activity
778+
# passes the "nothing to output" gate above, but no CPU sample was ever
779+
# recorded), or a run whose only CPU sample had total_time == 0. The
780+
# sibling per-file/per-line normalizations (lines ~556, ~1259) already
781+
# guard this; this site was missed. Same bug class as the leak-velocity
782+
# divide (see formal/README.md "Bugs the formalization found").
783+
if stats.cpu_stats.total_cpu_samples:
784+
for stk in list(stats.stacks):
785+
stack_stats = stats.stacks[stk]
786+
stats.stacks[stk] = StackStats(
787+
stack_stats.count,
788+
stack_stats.python_time / stats.cpu_stats.total_cpu_samples,
789+
stack_stats.c_time / stats.cpu_stats.total_cpu_samples,
790+
stack_stats.cpu_samples / stats.cpu_stats.total_cpu_samples,
791+
)
783792

784793
# Convert stacks into a representation suitable for JSON dumping.
785794
# Snapshot: stats.stacks is mutated from the CPU sampling signal handler.

scalene/scalene_output.py

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -696,7 +696,19 @@ def output_profiles(
696696
if len(leaks) > 0:
697697
# Report in descending order by least likelihood
698698
for leak in sorted(leaks, key=itemgetter(1), reverse=True):
699-
output_str = f"Possible memory leak identified at line {str(leak[0])} (estimated likelihood: {(leak[1] * 100):3.0f}%, velocity: {(leak[2] / stats.elapsed_time):3.0f} MB/s)"
699+
# Guard the velocity denominator: compute_leaks gates on
700+
# allocation growth rate, NOT wall-clock time, so a leak can
701+
# be reported when elapsed_time is still 0.0 (sub-ms run) →
702+
# ZeroDivisionError. This is the CLI-renderer twin of the
703+
# leak-velocity divide fixed in scalene_json.py (#1077); the
704+
# two output paths are separate (see Scalene-Debugging.md
705+
# "three renderers"), so the json.py fix did not cover it.
706+
velocity = (
707+
leak[2] / stats.elapsed_time
708+
if stats.elapsed_time > 0
709+
else 0.0
710+
)
711+
output_str = f"Possible memory leak identified at line {str(leak[0])} (estimated likelihood: {(leak[1] * 100):3.0f}%, velocity: {velocity:3.0f} MB/s)"
700712
console.print(output_str)
701713

702714
if self.html:
Lines changed: 73 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,73 @@
1+
"""Regression test for the CLI-renderer twin of the leak-velocity divide-by-zero.
2+
3+
Bug #1 (see formal/README.md "Bugs the formalization found", fixed in #1077)
4+
was an unguarded `leak_velocity / stats.elapsed_time` in the JSON renderer
5+
(`scalene_json.py`). Scalene has *three separate output renderers* (see
6+
Scalene-Debugging.md) — and the CLI renderer (`scalene_output.py`, used by
7+
`scalene view --cli`) had the identical unguarded divide:
8+
9+
velocity: {(leak[2] / stats.elapsed_time):3.0f} MB/s
10+
11+
`compute_leaks` gates on allocation *growth rate*, not wall-clock time, so a
12+
leak can be reported on a run short enough that `elapsed_time` is still `0.0`
13+
→ `ZeroDivisionError`. The #1077 fix only touched the JSON renderer; this one
14+
was missed. Found by re-running the denominator audit across the CLI path.
15+
16+
These tests pin the two facts the fix relies on:
17+
1. `compute_leaks` returns leaks with no dependence on elapsed_time, so the
18+
buggy site is reachable with elapsed_time == 0.
19+
2. The reported velocity is now computed without dividing by zero.
20+
"""
21+
22+
import math
23+
24+
from scalene.scalene_leak_analysis import ScaleneLeakAnalysis
25+
from scalene.scalene_statistics import (
26+
Filename,
27+
LineNumber,
28+
ScaleneStatistics,
29+
)
30+
31+
32+
def _cli_velocity(leak_velocity: float, elapsed_time: float) -> float:
33+
"""The (fixed) velocity computation from ScaleneOutput.output_profiles.
34+
35+
Mirrors the guarded expression at scalene_output.py:699 so the regression
36+
is pinned even though the full CLI render path needs heavy stats setup.
37+
"""
38+
return leak_velocity / elapsed_time if elapsed_time > 0 else 0.0
39+
40+
41+
def test_cli_leak_velocity_no_divide_by_zero_on_short_run():
42+
"""With elapsed_time == 0 (sub-millisecond run), the CLI leak report must
43+
not raise and must be finite."""
44+
v = _cli_velocity(leak_velocity=123.4, elapsed_time=0.0)
45+
assert v == 0.0
46+
assert math.isfinite(v)
47+
48+
49+
def test_cli_leak_velocity_normal_case():
50+
"""With positive elapsed_time the velocity is the usual ratio."""
51+
assert _cli_velocity(leak_velocity=100.0, elapsed_time=2.0) == 50.0
52+
53+
54+
def test_compute_leaks_independent_of_elapsed_time():
55+
"""compute_leaks gates on growth_rate, not elapsed_time — which is why the
56+
unguarded CLI division was reachable with elapsed_time == 0. Mirrors the
57+
JSON-renderer regression; kept here so the CLI path has its own guard."""
58+
stats = ScaleneStatistics()
59+
fname = Filename("prog.py")
60+
lineno = LineNumber(10)
61+
# An allocation that is never freed: high leak likelihood.
62+
stats.memory_stats.leak_score[fname][lineno] = (100, 0)
63+
stats.memory_stats.memory_malloc_samples[fname][lineno] = 100.0
64+
stats.memory_stats.memory_malloc_count[fname][lineno] = 100
65+
avg_mallocs = {lineno: 100.0}
66+
# A high growth rate triggers leak reporting regardless of elapsed_time
67+
# (which is left at its default 0.0 here).
68+
assert stats.elapsed_time == 0.0
69+
leaks = ScaleneLeakAnalysis.compute_leaks(1.0, stats, avg_mallocs, fname)
70+
# If any leak is reported, the CLI would have divided by elapsed_time == 0.
71+
for leak in leaks:
72+
v = _cli_velocity(leak[2], stats.elapsed_time)
73+
assert math.isfinite(v)
Lines changed: 129 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,129 @@
1+
"""Regression test for a divide-by-zero found by the Lean formalization.
2+
3+
Same bug class as `test_leak_velocity_zero_elapsed.py` (see
4+
formal/README.md "Bugs the formalization found"): an unguarded denominator
5+
whose zero-ness the surrounding invariants don't rule out.
6+
7+
The stacks-normalization loop in `ScaleneJSON.output_profiles` divided each
8+
recorded stack's timings by `stats.cpu_stats.total_cpu_samples`:
9+
10+
for stk in list(stats.stacks):
11+
stats.stacks[stk] = StackStats(
12+
stack_stats.count,
13+
stack_stats.python_time / stats.cpu_stats.total_cpu_samples,
14+
...
15+
16+
with no guard. `total_cpu_samples` can be 0 while `stats.stacks` is non-empty:
17+
a **memory-only run with `--stacks`** records stack entries (from the CPU
18+
sampler's stack collection) while memory activity — not CPU activity — is what
19+
passes the "nothing to output" gate at the top of `output_profiles`. With no
20+
CPU sample ever recorded, `total_cpu_samples` stays at its initial `0.0`, and
21+
the loop raises `ZeroDivisionError`. The sibling per-file / per-line
22+
normalizations (guarded by `if stats.cpu_stats.total_cpu_samples:` and a
23+
try/except) already handled this; this site was missed.
24+
25+
This test drives the *full* `output_profiles` path (it reaches the buggy loop),
26+
so it genuinely crashes on the pre-fix code and passes after the guard.
27+
"""
28+
29+
from pathlib import Path
30+
31+
from scalene.scalene_json import ScaleneJSON
32+
from scalene.scalene_statistics import (
33+
Filename,
34+
LineNumber,
35+
ScaleneStatistics,
36+
StackStats,
37+
)
38+
39+
40+
def _memory_only_stats_with_stacks() -> ScaleneStatistics:
41+
"""A stats object as produced by a memory-only run with --stacks: memory
42+
samples recorded, a stack recorded, but no CPU sample (total_cpu_samples
43+
still 0.0)."""
44+
stats = ScaleneStatistics()
45+
fname = Filename("prog.py")
46+
lineno = LineNumber(10)
47+
# Memory activity: passes the "nothing to output" gate in output_profiles.
48+
stats.memory_stats.total_memory_malloc_samples = 5.0
49+
stats.memory_stats.memory_malloc_samples[fname][lineno] = 5.0
50+
stats.memory_stats.memory_malloc_count[fname][lineno] = 1
51+
# A stack was recorded by the CPU sampler's --stacks collection...
52+
stats.stacks[((fname, "func", lineno),)] = StackStats(1, 0.5, 0.5, 1.0)
53+
# ...but no CPU sample fired, so the normalization denominator is 0.
54+
assert stats.cpu_stats.total_cpu_samples == 0.0
55+
assert stats.stacks
56+
return stats
57+
58+
59+
def test_output_profiles_no_divide_by_zero_with_stacks_and_zero_cpu():
60+
"""output_profiles must not raise ZeroDivisionError when stacks are present
61+
but total_cpu_samples is 0 (memory-only run with --stacks)."""
62+
stats = _memory_only_stats_with_stacks()
63+
j = ScaleneJSON()
64+
# Would raise ZeroDivisionError at scalene_json.py:779 before the fix.
65+
result = j.output_profiles(
66+
Filename("prog.py"),
67+
stats,
68+
1234,
69+
lambda f, l: True,
70+
Path("/tmp"),
71+
Filename("prog.py"),
72+
Filename("prog.py"),
73+
[],
74+
profile_memory=True,
75+
reduced_profile=False,
76+
)
77+
assert isinstance(result, dict)
78+
assert result # non-empty: memory activity produces output
79+
80+
81+
def test_stacks_left_unnormalized_when_no_cpu_samples():
82+
"""When total_cpu_samples is 0 the raw stack entry is preserved rather than
83+
normalized (the correct fallback: you can't normalize by zero total)."""
84+
stats = _memory_only_stats_with_stacks()
85+
key = ((Filename("prog.py"), "func", LineNumber(10)),)
86+
before = stats.stacks[key]
87+
j = ScaleneJSON()
88+
j.output_profiles(
89+
Filename("prog.py"),
90+
stats,
91+
1234,
92+
lambda f, l: True,
93+
Path("/tmp"),
94+
Filename("prog.py"),
95+
Filename("prog.py"),
96+
[],
97+
profile_memory=True,
98+
reduced_profile=False,
99+
)
100+
after = stats.stacks[key]
101+
# Unchanged: timings not divided by zero, count preserved.
102+
assert after.count == before.count
103+
assert after.python_time == before.python_time
104+
assert after.c_time == before.c_time
105+
106+
107+
def test_output_profiles_normalizes_stacks_when_cpu_samples_present():
108+
"""Sanity: with CPU samples present the loop still runs and normalizes."""
109+
stats = _memory_only_stats_with_stacks()
110+
stats.cpu_stats.total_cpu_samples = 2.0
111+
key = ((Filename("prog.py"), "func", LineNumber(10)),)
112+
j = ScaleneJSON()
113+
j.output_profiles(
114+
Filename("prog.py"),
115+
stats,
116+
1234,
117+
lambda f, l: True,
118+
Path("/tmp"),
119+
Filename("prog.py"),
120+
Filename("prog.py"),
121+
[],
122+
profile_memory=True,
123+
reduced_profile=False,
124+
)
125+
after = stats.stacks[key]
126+
# 0.5 python_time / 2.0 total = 0.25, etc.
127+
assert after.python_time == 0.25
128+
assert after.c_time == 0.25
129+
assert after.cpu_samples == 0.5

0 commit comments

Comments
 (0)