Skip to content

Per-path profiling, child-call kind, and call columns - #77

Merged
revarbat merged 4 commits into
mainfrom
profiling-data
Aug 7, 2026
Merged

Per-path profiling, child-call kind, and call columns#77
revarbat merged 4 commits into
mainfrom
profiling-data

Conversation

@revarbat

@revarbat revarbat commented Aug 7, 2026

Copy link
Copy Markdown
Member

Three changes to the profiler's data model. All were held back by the
Actions outage; they were developed on top of #76 and are rebased onto
main now that it has merged.

Per-path profiling (0.19.0)

ProfileResult gains paths: a calling-context tree, one node per call
site reached by one specific path from <toplevel>. Where callSites
aggregates a site over every path that reached it, this keeps them
apart — so cuboid called from bracket and cuboid called from rail
have their own times, and a consumer can show what a particular path
actually cost.

Flat vector with parent/child indices, not pointers: it survives the
vector reallocating and crosses the Python binding as plain data.

Recursion folds rather than unrolling — re-entering a site already on the
path reuses that node, so 400-deep recursion is one node with
callCount 400.

Cumulative time is derived bottom-up in finalizeProfilePaths() rather
than measured per entry. Measuring per entry counted only the outermost
entry at a fold while children accumulated across all of them, which
broke containment: 6 of 9217 nodes had children summing past their
parent.

child kind (0.20.0)

module foo(x) { foo(x+1); } and foo() foo(); both produce a foo→foo
edge, but only the first is recursion — the second hands foo to foo as a
child. Reporting both as "module" invites reading one as the other.

EvalContext gains viaChildren, set where prepareChildrenForward
builds the forwarding context so both its return paths carry it. It
propagates through withScope/childCtx (a forwarded translate() foo()
is still child-passing) but callCtx resets it, so entering a body ends
the forwarding. buildModuleChildCtx is the single funnel every module
call goes through, native and VM alike; enterUserCall consumes the flag,
so a plain call inside a forwarded body stays an ordinary module call.

Call column (0.21.0)

m(); m(); is two call sites, but keyed by (kind, name, origin, line)
they aggregated into one entry: one row carrying both calls' time with a
call count of 2. f(g(x)) and foo() foo(); had the same problem.

Column now sits in ProfileSiteKey and in the tree's fold and sibling
match. CallSiteProfile and ProfilePathNode both carry callColumn;
the bindings expose call_column. The CLI report shows
file:line:column, gains a call_column CSV field, and its sort
tie-break follows the key — otherwise two sites on one line order
arbitrarily between runs.

Tests

1407 pass. New coverage for the child/recursion distinction, that the
flag does not leak into a forwarded body, and that two calls on one line
stay two call sites and two tree nodes.

The containment test was rewritten after it passed against the broken
implementation — its original fixture had no recursion through a module
call, so it never exercised the case it existed for. It now asserts
multiEntry > 0 to guard the fixture itself.

🤖 Generated with Claude Code

Revar Desmera and others added 4 commits August 6, 2026 18:23
ProfileResult.callSites aggregates each call site over every path that
reached it, so a report could say "cuboid is expensive" but never
"expensive WHEN CALLED FROM HERE". BelfrySCAD's profile tree had to
approximate the hierarchy from caller names, which meant a nested row's
times were totals across all callers rather than that path's own.

ProfileResult.paths is now a real calling-context tree: each node is one
call site on ONE path from <toplevel>, with its own count and times.

    <toplevel>            156.04ms
      bracket             122.62ms (78.6%)
        translate         122.58ms
          diff            122.19ms
            cuboid         74.13ms (47.5%)

A flat vector with parent/child indices, not pointers -- survives the
vector growing, and crosses the binding as plain data. callSites is
unchanged: the flat view is still the right answer to "what is expensive
overall" and is cheaper to scan.

Recursion folds rather than unrolling: re-entering a site already on the
path reuses that node (callCount rises) instead of appending one per
level, so a 200-deep recursion is one node, not 200. A 200k-node cap
backstops pathological cases by folding onto the parent -- totals stay
honest, the tree just stops subdividing.

Cumulative time is DERIVED from the subtree (selfTime plus children),
not measured per entry. Measuring it is wrong precisely where recursion
folds: every level lands on the same node, so only the outermost entry
may add its elapsed or nested time double-counts -- yet the calls each
level makes still attach as that node's children, leaving the node
reading smaller than its own subtree. A real model showed a _translate
with 22.85ms and 90.09ms of children, 6 such nodes in 9217. Self time
has no such problem (disjoint by construction via the child-time stack),
so cumulative built from it can never contradict the subtree. Verified:
0 containment violations across three models, root within 0.4% of
resolveTime.

The first version of the containment test passed against the broken
implementation -- its fixture had no recursion through a module call, the
only shape that triggers the fold. It now recurses deliberately and
asserts the fixture actually produced a multi-entry node, so it cannot
silently stop testing what it exists for.

Minor bump: new field, no existing behaviour changed.
Both `module foo(x) { foo(x+1); }` and `foo() foo();` produce a foo->foo
edge in the call tree, but only the first is recursion. The second hands
foo to foo as a child, which is an entirely different shape of call, and a
profile that reports both as "module" invites reading one as the other.

EvalContext gains a viaChildren flag, set where prepareChildrenForward
builds the forwarding context so both of its return paths carry it (bare
children() and indexed children(i)). It propagates through withScope and
childCtx -- a forwarded `translate() foo()` is still child-passing -- but
callCtx resets it by omission, so entering a body ends the forwarding.

buildModuleChildCtx is the single funnel every module call goes through,
native and VM alike, so copying the caller's flag onto the body context
there is enough to reach enterUserCall, which consumes it: the body's own
statements run in that same context, and a plain call among them is an
ordinary module call, not a child.

Kind now also participates in the call-tree fold key, so recursion and
child-passing no longer collapse onto one node.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`m(); m();` is two call sites, but keyed by (kind, name, origin, line)
they aggregated into one entry: one row carrying both calls' time and a
call count of 2, with no way to tell which of the two was expensive. The
call tree collapsed them onto one node for the same reason. `f(g(x))` and
`foo() foo();` have the same problem.

Column now sits in ProfileSiteKey and in the tree's fold and sibling
match, so the two stay separate. CallSiteProfile and ProfilePathNode both
carry callColumn; the bindings expose it as call_column.

The CLI report shows file:line:column and gains a call_column CSV field,
and the sort tie-break follows the key -- otherwise two sites on one line
would order arbitrarily between runs.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Three ProfilePaths tests recursed 40-400 levels deep. kMaxUserCallDepth is
30, and only the compiled path may skip that guard, so they passed with
the bytecode VM on and died with 'Recursion too deep' with it off -- which
is the second pass CI runs and the one that caught this.

Depths are now well under 30. Where a test needed one call to cost
measurably more than another, that contrast now comes from per-call work
(a list comprehension) rather than from depth, which is what made the deep
fixtures tempting in the first place.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@revarbat
revarbat merged commit 8e54284 into main Aug 7, 2026
3 checks passed
@revarbat
revarbat deleted the profiling-data branch August 7, 2026 03:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant