Per-path profiling, child-call kind, and call columns - #77
Merged
Conversation
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>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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)
ProfileResultgainspaths: a calling-context tree, one node per callsite reached by one specific path from
<toplevel>. WherecallSitesaggregates a site over every path that reached it, this keeps them
apart — so
cuboidcalled frombracketandcuboidcalled fromrailhave 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
callCount400.Cumulative time is derived bottom-up in
finalizeProfilePaths()ratherthan 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.
childkind (0.20.0)module foo(x) { foo(x+1); }andfoo() foo();both produce afoo→fooedge, 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.EvalContextgainsviaChildren, set whereprepareChildrenForwardbuilds the forwarding context so both its return paths carry it. It
propagates through
withScope/childCtx(a forwardedtranslate() foo()is still child-passing) but
callCtxresets it, so entering a body endsthe forwarding.
buildModuleChildCtxis the single funnel every modulecall goes through, native and VM alike;
enterUserCallconsumes 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))andfoo() foo();had the same problem.Column now sits in
ProfileSiteKeyand in the tree's fold and siblingmatch.
CallSiteProfileandProfilePathNodeboth carrycallColumn;the bindings expose
call_column. The CLI report showsfile:line:column, gains acall_columnCSV field, and its sorttie-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 > 0to guard the fixture itself.🤖 Generated with Claude Code