From ae430d36f803225e96ce729d62cb6e9754b763a4 Mon Sep 17 00:00:00 2001 From: Revar Desmera Date: Thu, 6 Aug 2026 13:46:39 -0700 Subject: [PATCH 1/4] Add per-path profiling: a calling-context tree 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 , with its own count and times. 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. --- bindings/module.cpp | 25 +++- include/openscad_cpp_evaluator/evaluator.hpp | 35 +++++ include/openscad_cpp_evaluator/profile.hpp | 36 +++++ pyproject.toml | 2 +- python/openscad_cpp_evaluator/__init__.py | 19 ++- src/csg_resolve.cpp | 4 +- src/debug_profile.cpp | 95 +++++++++++- tests/test_profiling.cpp | 143 +++++++++++++++++++ 8 files changed, 354 insertions(+), 5 deletions(-) diff --git a/bindings/module.cpp b/bindings/module.cpp index 71fe9c8..18a83d8 100644 --- a/bindings/module.cpp +++ b/bindings/module.cpp @@ -249,7 +249,30 @@ nb::object profileResultToPy(const std::optional& pr) sites.append(facadeAttr("CallSiteProfile")(s.kind, s.name, s.callerName, s.callOrigin, s.callLine, s.declOrigin, s.declLine, s.callCount, s.selfTime, s.cumulativeTime)); } - return facadeAttr("ProfileResult")(sites, pr->resolveTime, pr->generateTime, pr->totalTime, pr->unattributedTime); + // The calling-context tree, as plain dicts. Parent/child INDICES, not + // nested objects: the C++ side is already a flat vector keyed that way, + // and a self-referential nesting would have to be rebuilt here for no + // gain -- a consumer walks it by index just as C++ does. + nb::list paths; + for (const oscadeval::ProfilePathNode& n : pr->paths) { + nb::dict d; + d["parent"] = n.parent; + nb::list kids; + for (int c : n.children) kids.append(c); + d["children"] = kids; + d["kind"] = n.kind; + d["name"] = n.name; + d["call_origin"] = n.callOrigin; + d["call_line"] = n.callLine; + d["decl_origin"] = n.declOrigin; + d["decl_line"] = n.declLine; + d["call_count"] = n.callCount; + d["self_time"] = n.selfTime; + d["cumulative_time"] = n.cumulativeTime; + paths.append(d); + } + return facadeAttr("ProfileResult")(sites, pr->resolveTime, pr->generateTime, pr->totalTime, pr->unattributedTime, + paths); } // ctx.dyn / ctx.dynExplicit -> (dict[str, Any], set[str]) -- every currently- diff --git a/include/openscad_cpp_evaluator/evaluator.hpp b/include/openscad_cpp_evaluator/evaluator.hpp index 46d6bb3..b461a0c 100644 --- a/include/openscad_cpp_evaluator/evaluator.hpp +++ b/include/openscad_cpp_evaluator/evaluator.hpp @@ -1252,6 +1252,13 @@ class Evaluator { ProfileSiteKey key; bool recursiveReentry; std::chrono::steady_clock::time_point start; + // Node this call occupies in the calling-context tree, and the one + // to restore on exit. `pathRecursive` is the per-PATH equivalent of + // recursiveReentry: true when this entry folded back onto a node + // already on the path, so only the outermost entry adds cumulative + // time -- the same rule callSites uses, applied per node. + int pathNode = -1; + int pathPrev = -1; }; std::optional profileEnter(const std::string& kind, const std::string& name, const oscad::Position* callPos, const oscad::Position* declPos); @@ -1712,6 +1719,34 @@ class Evaluator { std::map profileSites_; std::set profileActive_; // site keys with a call currently on callStack_ std::vector profileChildTime_; // parallel aux stack to callStack_ + + // Calling-context tree (see ProfilePathNode). profilePaths_[0] is the + // root, created lazily on the first profiled call; + // profileCurrentPath_ is the node the running call belongs to, so a + // profileEnter knows which parent to hang its node off. + std::vector profilePaths_; + int profileCurrentPath_ = -1; + + // Safety valve. The tree is bounded by distinct ACYCLIC paths (see + // ProfilePathNode on recursion folding), which is finite but can still + // be large for a deeply-layered library. Past this, no new nodes are + // created and further calls fold onto their parent -- the report stays + // truthful about totals and simply stops subdividing, rather than the + // profiler becoming the thing that runs out of memory. + static constexpr size_t kMaxProfilePathNodes = 200000; + + // Finds-or-creates the child of profileCurrentPath_ for this call site + // and returns its index. Sets `folded` when the returned node was + // already on the current path (recursion, or the node cap) rather than + // a fresh or sibling child -- the caller must then skip cumulative + // time for this entry, exactly as recursiveReentry does for callSites. + int profilePathEnter(const std::string& kind, const std::string& name, const std::string& callOrigin, + int callLine, const oscad::Position* declPos, bool& folded); + + // Fills in every node's cumulativeTime as selfTime + the cumulative of + // its children, bottom-up. See profileExit for why this is derived + // rather than measured. + void finalizeProfilePaths(); }; } // namespace oscadeval diff --git a/include/openscad_cpp_evaluator/profile.hpp b/include/openscad_cpp_evaluator/profile.hpp index d6b4c5b..13c2fa0 100644 --- a/include/openscad_cpp_evaluator/profile.hpp +++ b/include/openscad_cpp_evaluator/profile.hpp @@ -25,6 +25,37 @@ struct CallSiteProfile { double cumulativeTime = 0.0; // seconds, includes children; recursion-guarded }; +// One node of the calling-context tree: a call site reached by ONE +// specific path from . Where CallSiteProfile aggregates a site +// over every path that reached it, this keeps them separate -- so +// `cuboid` called from `bracket` and `cuboid` called from `rail` are two +// nodes with their own times, and a consumer can show what a particular +// path actually cost rather than a total across all callers. +// +// Flat vector with parent/child indices rather than pointers: it survives +// the vector reallocating as nodes are appended, and crosses the Python +// binding as plain data with no ownership question. +// +// Recursion is folded rather than unrolled. Re-entering a call site +// already on the current path reuses that node instead of appending a new +// child, so `fib` calling itself 400 deep is one node with callCount 400, +// not a 400-node chain. That bounds the tree by distinct ACYCLIC paths and +// keeps the recursion-guarded cumulative-time rule (only the outermost +// entry contributes) meaningful per node. +struct ProfilePathNode { + int parent = -1; // index into ProfileResult::paths; -1 for the root + std::vector children; // indices, in first-call order + std::string kind; // "module" | "function"; empty for the root + std::string name; // callee; "" for the root + std::string callOrigin; + int callLine = 0; + std::string declOrigin; + int declLine = 0; + int callCount = 0; + double selfTime = 0.0; // seconds, this node's own code on this path + double cumulativeTime = 0.0; // seconds, this node and everything under it +}; + // Whole-evaluate() profiling summary, built when Evaluator is constructed // with profiling=true. unattributedTime covers top-level script code and // anything else not inside a user module/function call (native builtins' @@ -34,6 +65,11 @@ struct CallSiteProfile { // ProfileResult. struct ProfileResult { std::vector callSites; + // The calling-context tree; paths[0] is always the root. + // Empty only if profiling was off. callSites stays exactly as it was -- + // the flat per-site view is still the right answer to "what is + // expensive overall", and is cheaper to scan than walking this. + std::vector paths; double resolveTime = 0.0; double generateTime = 0.0; double totalTime = 0.0; diff --git a/pyproject.toml b/pyproject.toml index 5afced5..7a2ec03 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "scikit_build_core.build" [project] name = "openscad_cpp_evaluator" -version = "0.18.0" +version = "0.19.0" description = "C++ OpenSCAD evaluator with Python bindings" readme = "README.md" requires-python = ">=3.12" diff --git a/python/openscad_cpp_evaluator/__init__.py b/python/openscad_cpp_evaluator/__init__.py index 96ed656..1e724d0 100644 --- a/python/openscad_cpp_evaluator/__init__.py +++ b/python/openscad_cpp_evaluator/__init__.py @@ -9,7 +9,7 @@ `cb.body.to_mesh().vert_properties/tri_verts/run_original_id/run_index` exactly as before -- no cross-module Manifold objects are ever exchanged. """ -from dataclasses import dataclass +from dataclasses import dataclass, field from typing import Optional from . import _openscad_cpp_evaluator as _ext @@ -165,6 +165,23 @@ class ProfileResult: generate_time: float total_time: float unattributed_time: float + # Calling-context tree: a flat list of dicts, paths[0] the + # root, linked by `parent`/`children` INDICES into this same list. + # + # Where call_sites aggregates a site over every path that reached it, + # each node here is one call site on ONE path -- so `cuboid` called + # from `bracket` and from `rail` are separate nodes with their own + # times, and a report can say what a particular path cost rather than + # only what a name cost in total. + # + # Keys: parent, children, kind, name, call_origin, call_line, + # decl_origin, decl_line, call_count, self_time, cumulative_time. + # + # Recursion is folded: re-entering a site already on the path reuses + # that node (call_count rises) instead of unrolling a node per level. + # Defaults to empty so a ProfileResult built by older code still + # constructs. + paths: list = field(default_factory=list) def _summarize_param(value, max_items: int = 6, max_len: int = 40) -> str: diff --git a/src/csg_resolve.cpp b/src/csg_resolve.cpp index 82ce931..4cf25e0 100644 --- a/src/csg_resolve.cpp +++ b/src/csg_resolve.cpp @@ -269,8 +269,10 @@ std::vector Evaluator::evaluateImpl(const NodeList& nodes, EvalCont selfSum += site.selfTime; sites.push_back(site); } + finalizeProfilePaths(); profileResult = ProfileResult{ - std::move(sites), resolveTime, generateTime, resolveTime + generateTime, std::max(0.0, resolveTime - selfSum), + std::move(sites), profilePaths_, resolveTime, generateTime, resolveTime + generateTime, + std::max(0.0, resolveTime - selfSum), }; } diff --git a/src/debug_profile.cpp b/src/debug_profile.cpp index f73cf91..1d9172a 100644 --- a/src/debug_profile.cpp +++ b/src/debug_profile.cpp @@ -116,6 +116,64 @@ void Evaluator::checkDebug(const oscad::ASTNode& node, EvalContext& ctx, bool fo if (action.stop) throw EvalError(kDebuggingStoppedMessage); } +int Evaluator::profilePathEnter(const std::string& kind, const std::string& name, const std::string& callOrigin, + int callLine, const oscad::Position* declPos, bool& folded) { + folded = false; + if (profilePaths_.empty()) { + ProfilePathNode root; + root.name = ""; + profilePaths_.push_back(std::move(root)); + profileCurrentPath_ = 0; + } + const int parent = profileCurrentPath_ < 0 ? 0 : profileCurrentPath_; + + // Already on this path? Fold onto that node rather than growing a chain + // per recursive level (see ProfilePathNode). + for (int walk = parent; walk > 0; walk = profilePaths_[static_cast(walk)].parent) { + const ProfilePathNode& n = profilePaths_[static_cast(walk)]; + if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && n.kind == kind) { + folded = true; // recursion: this site is already open on this path + return walk; + } + } + for (int childIdx : profilePaths_[static_cast(parent)].children) { + const ProfilePathNode& n = profilePaths_[static_cast(childIdx)]; + if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && n.kind == kind) { + return childIdx; + } + } + if (profilePaths_.size() >= kMaxProfilePathNodes) { + folded = true; // cap reached: stop subdividing, keep totals honest + return parent; + } + + ProfilePathNode node; + node.parent = parent; + node.kind = kind; + node.name = name; + node.callOrigin = callOrigin; + node.callLine = callLine; + node.declOrigin = declPos ? declPos->origin : ""; + node.declLine = declPos ? declPos->line : 0; + const int idx = static_cast(profilePaths_.size()); + profilePaths_.push_back(std::move(node)); + profilePaths_[static_cast(parent)].children.push_back(idx); + return idx; +} + +void Evaluator::finalizeProfilePaths() { + // Children always have a higher index than their parent (a node is + // appended when first reached, and folding never creates an edge back + // to an ancestor), so one reverse sweep resolves the whole tree with + // no recursion and no risk of an unbounded native stack. + for (size_t i = profilePaths_.size(); i-- > 0;) { + ProfilePathNode& n = profilePaths_[i]; + double total = n.selfTime; + for (int c : n.children) total += profilePaths_[static_cast(c)].cumulativeTime; + n.cumulativeTime = total; + } +} + std::optional Evaluator::profileEnter(const std::string& kind, const std::string& name, const oscad::Position* callPos, const oscad::Position* declPos) { if (!profiling_) return std::nullopt; @@ -146,7 +204,17 @@ std::optional Evaluator::profileEnter(const std::strin const bool recursiveReentry = profileActive_.count(key) > 0; if (!recursiveReentry) profileActive_.insert(key); profileChildTime_.push_back(0.0); - return ProfileHandle{key, recursiveReentry, std::chrono::steady_clock::now()}; + + const int prevPath = profileCurrentPath_; + bool folded = false; // only affects node reuse now, not accounting + const int pathNode = profilePathEnter(kind, name, callOrigin, callLine, declPos, folded); + profilePaths_[static_cast(pathNode)].callCount += 1; + profileCurrentPath_ = pathNode; + + ProfileHandle handle{key, recursiveReentry, std::chrono::steady_clock::now()}; + handle.pathNode = pathNode; + handle.pathPrev = prevPath; + return handle; } void Evaluator::profileRecordTailHop(const std::string& kind, const std::string& name, const oscad::Position* callPos, @@ -199,6 +267,31 @@ void Evaluator::profileExit(const ProfileHandle& handle) { site.cumulativeTime += elapsed; profileActive_.erase(handle.key); } + + // Same accounting, but attributed to this call's own node in the + // calling-context tree rather than to the site aggregated over every + // path that reached it. + if (handle.pathNode >= 0 && static_cast(handle.pathNode) < profilePaths_.size()) { + // Self time only. Cumulative is DERIVED from the subtree once the + // run finishes (finalizeProfilePaths), not measured here. + // + // Measuring it per entry is wrong at a fold point: when a site + // recurses, every level lands on the same node, but only the + // outermost entry may add its elapsed (or nested time double- + // counts) -- while the calls made from every level still attach as + // that node's children. The node then reads smaller than the + // children under it. Found on a real model: a `_translate` entered + // 7 times via recursion showed 22.85ms with 90.09ms of children. + // + // Self time has no such problem: it is disjoint by construction + // (the child-time stack subtracts nested work), so summing it + // across every entry is exactly this node's own cost on this path, + // and cumulative built from it can never contradict the subtree. + ProfilePathNode& node = profilePaths_[static_cast(handle.pathNode)]; + node.selfTime += elapsed - childTime; + profileCurrentPath_ = handle.pathPrev; + } + if (!profileChildTime_.empty()) profileChildTime_.back() += elapsed; } diff --git a/tests/test_profiling.cpp b/tests/test_profiling.cpp index 4235e7f..50528c6 100644 --- a/tests/test_profiling.cpp +++ b/tests/test_profiling.cpp @@ -16,6 +16,18 @@ const CallSiteProfile* findSite(const ProfileResult& r, const std::string& kind, return nullptr; } +// Runs `code` with profiling on and returns the result. `ast`/`scope` are +// kept alive by the caller's Evaluator, which owns nothing that outlives +// this -- ProfileResult is plain data. +ProfileResult profileSrc(const std::string& code) { + Evaluator ev(EchoFn{}, nullptr, nullptr, DebugHooks{}, /*profiling=*/true); + auto ast = parseSrc(code); + auto scope = oscad::buildScopes(ast); + EvalContext ctx = EvalContext::makeRoot(scope.get()); + ev.evaluate(ast, ctx); + return ev.profileResult.value_or(ProfileResult{}); +} + } // namespace TEST(Profiling, DisabledByDefaultLeavesProfileResultEmpty) { @@ -125,3 +137,134 @@ TEST(Profiling, GenerateTimeAndTotalTimeAreNonNegative) { EXPECT_GE(ev.profileResult->resolveTime, 0.0); EXPECT_NEAR(ev.profileResult->totalTime, ev.profileResult->resolveTime + ev.profileResult->generateTime, 1e-9); } + +// -- Calling-context tree (per-path attribution) --------------------------- + +namespace { +const oscadeval::ProfilePathNode* childNamed(const oscadeval::ProfileResult& r, + const oscadeval::ProfilePathNode& parent, + const std::string& name) { + for (int idx : parent.children) { + const auto& n = r.paths[static_cast(idx)]; + if (n.name == name) return &n; + } + return nullptr; +} +} // namespace + +// The point of the tree: the same callee reached by two different callers +// gets two nodes with their own times, where callSites has one entry +// totalling both. Without that, a report can say "helper is expensive" but +// never "expensive *when called from here*". +TEST(ProfilePaths, SameCalleeUnderTwoCallersGetsSeparateNodes) { + const ProfileResult r = profileSrc( + "function work(n) = n <= 0 ? 0 : work(n - 1) + 1;\n" + "module light() { x = work(20); cube(1); }\n" + "module heavy() { x = work(400); cube(1); }\n" + "light();\n" + "heavy();\n"); + ASSERT_FALSE(r.paths.empty()); + const auto& root = r.paths[0]; + EXPECT_EQ(root.name, ""); + + const auto* light = childNamed(r, root, "light"); + const auto* heavy = childNamed(r, root, "heavy"); + ASSERT_NE(light, nullptr); + ASSERT_NE(heavy, nullptr); + + const auto* workUnderLight = childNamed(r, *light, "work"); + const auto* workUnderHeavy = childNamed(r, *heavy, "work"); + ASSERT_NE(workUnderLight, nullptr); + ASSERT_NE(workUnderHeavy, nullptr); + // Two distinct nodes for the same callee -- the whole point. + EXPECT_NE(workUnderLight, workUnderHeavy); + // ...and the expensive path is attributed the larger share. This is the + // fact the aggregated view cannot express at all. + EXPECT_GT(workUnderHeavy->cumulativeTime, workUnderLight->cumulativeTime); + + // The flat view still totals both, unchanged. + double siteTotal = 0.0; + for (const auto& s : r.callSites) { + if (s.name == "work") siteTotal += s.cumulativeTime; + } + EXPECT_GT(siteTotal, 0.0); +} + +// Recursion folds onto one node instead of unrolling into a chain per +// level, or a 400-deep recursion would be 400 nodes. +TEST(ProfilePaths, RecursionFoldsOntoASingleNode) { + const ProfileResult r = profileSrc( + "function down(n) = n <= 0 ? 0 : down(n - 1) + 1;\n" + "x = down(200);\n" + "cube(x > 0 ? 1 : 2);\n"); + ASSERT_FALSE(r.paths.empty()); + size_t downNodes = 0; + for (const auto& n : r.paths) { + if (n.name == "down") ++downNodes; + } + // One node for the outer call plus one for the folded recursive site -- + // emphatically not one per level. + EXPECT_LE(downNodes, 2u) << downNodes; + EXPECT_LT(r.paths.size(), 20u) << r.paths.size(); +} + +// A node's cumulative time must cover its subtree, or percentages in a +// report are meaningless. +// +// The fixture deliberately RECURSES THROUGH A MODULE CALL, because that is +// what broke the first implementation and what a simple non-recursive +// fixture cannot catch. Recursion makes every level fold onto the same +// node for the sites inside the recursive body (here the `translate` and +// its internal `_translate`), so those nodes are entered many times while +// the calls each level makes still attach as their children. Measuring +// cumulative per entry -- counting only the outermost, to avoid double- +// counting nested time -- made the node read SMALLER than its own +// subtree. On a real model a `_translate` showed 22.85ms with 90.09ms of +// children. Cumulative is derived from the subtree now, so this holds by +// construction. +TEST(ProfilePaths, CumulativeTimeContainsChildrenEvenThroughRecursion) { + const ProfileResult r = profileSrc( + "function work(n) = n <= 0 ? 0 : work(n - 1) + 1;\n" + "module step(n) {\n" + " x = work(40);\n" + " cube(1);\n" + " if (n > 0) translate([0, 0, 2]) step(n - 1);\n" + "}\n" + "module outer() { step(6); }\n" + "outer();\n"); + ASSERT_FALSE(r.paths.empty()); + EXPECT_GT(r.paths[0].cumulativeTime, 0.0); + + size_t multiEntry = 0; + for (const auto& n : r.paths) { + double childSum = 0.0; + for (int c : n.children) childSum += r.paths[static_cast(c)].cumulativeTime; + EXPECT_LE(childSum, n.cumulativeTime + 1e-9) + << n.name << " (cum " << n.cumulativeTime << " < children " << childSum << ")"; + EXPECT_GE(n.cumulativeTime, n.selfTime - 1e-9) << n.name; + if (n.callCount > 1) ++multiEntry; + } + // Guard the fixture itself: if nothing folded, this test would pass + // without ever exercising the case it exists for. + EXPECT_GT(multiEntry, 0u) << "fixture never produced a multi-entry node"; +} + +// The root accounts for essentially the whole resolve pass -- the gap is +// top-level work outside any user call, which is what unattributedTime is. +TEST(ProfilePaths, RootCoversTheProfiledWork) { + const ProfileResult r = profileSrc( + "module m() { cube(1); }\nm(); m(); m();\n"); + ASSERT_FALSE(r.paths.empty()); + EXPECT_GT(r.paths[0].cumulativeTime, 0.0); + EXPECT_LE(r.paths[0].cumulativeTime, r.resolveTime + 1e-9); +} + +// Profiling off must cost nothing and produce no tree. +TEST(ProfilePaths, NoTreeWhenProfilingIsOff) { + Evaluator ev; // profiling off + auto ast = parseSrc("module m() { cube(1); }\nm();"); + auto scope = oscad::buildScopes(ast); + EvalContext ctx = EvalContext::makeRoot(scope.get()); + ev.evaluate(ast, ctx); + EXPECT_FALSE(ev.profileResult.has_value()); +} From f5f27726f574c812039460940b621d9b8f84d03a Mon Sep 17 00:00:00 2001 From: Revar Desmera Date: Thu, 6 Aug 2026 15:09:41 -0700 Subject: [PATCH 2/4] Profile a children()-forwarded module call as kind "child" 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) --- .../openscad_cpp_evaluator/eval_context.hpp | 15 +++++++ include/openscad_cpp_evaluator/profile.hpp | 4 +- pyproject.toml | 2 +- src/eval_context.cpp | 1 + src/user_calls.cpp | 15 ++++++- tests/test_profiling.cpp | 41 +++++++++++++++++++ 6 files changed, 74 insertions(+), 4 deletions(-) diff --git a/include/openscad_cpp_evaluator/eval_context.hpp b/include/openscad_cpp_evaluator/eval_context.hpp index 2905836..6528a8d 100644 --- a/include/openscad_cpp_evaluator/eval_context.hpp +++ b/include/openscad_cpp_evaluator/eval_context.hpp @@ -59,6 +59,21 @@ struct EvalContext { std::shared_ptr childrenNodes; const EvalContext* childrenCallerCtx = nullptr; + // True while evaluating statements that a children() forwarded, so a + // module call reached this way profiles as kind "child" rather than + // "module". `foo() foo();` and `module foo() { foo(); }` both produce a + // foo->foo edge, but only the second is recursion, and a profile that + // cannot tell them apart is misleading. + // + // Propagates through withScope/childCtx (a forwarded `translate() + // foo()` is still child-passing) but NOT through callCtx, which resets + // it by omission -- entering a body ends the forwarding. The one + // deliberate exception is buildModuleChildCtx, which copies the + // caller's flag onto the body ctx so enterUserCall can read it there; + // enterUserCall then clears it, so the call it describes is the only + // one that sees it. + bool viaChildren = false; + // The one genuinely fresh construction: seeds `dyn` with OpenSCAD's // built-in $-variable defaults ($fn=0, $fa=12, $fs=2, $t=0, // $parent_modules=0). Every other EvalContext in a run is derived diff --git a/include/openscad_cpp_evaluator/profile.hpp b/include/openscad_cpp_evaluator/profile.hpp index 13c2fa0..88b853e 100644 --- a/include/openscad_cpp_evaluator/profile.hpp +++ b/include/openscad_cpp_evaluator/profile.hpp @@ -13,7 +13,7 @@ namespace oscadeval { // node (and thus its position) is identical across those invocations. // Mirrors the reference's CallSiteProfile. struct CallSiteProfile { - std::string kind; // "module" | "function" + std::string kind; // "module" | "child" (forwarded via children()) | "function" std::string name; std::string callerName; // enclosing module/function's own name, or "" std::string callOrigin; @@ -45,7 +45,7 @@ struct CallSiteProfile { struct ProfilePathNode { int parent = -1; // index into ProfileResult::paths; -1 for the root std::vector children; // indices, in first-call order - std::string kind; // "module" | "function"; empty for the root + std::string kind; // "module" | "child" | "function"; empty for the root std::string name; // callee; "" for the root std::string callOrigin; int callLine = 0; diff --git a/pyproject.toml b/pyproject.toml index 7a2ec03..f10a3b9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "scikit_build_core.build" [project] name = "openscad_cpp_evaluator" -version = "0.19.0" +version = "0.20.0" description = "C++ OpenSCAD evaluator with Python bindings" readme = "README.md" requires-python = ">=3.12" diff --git a/src/eval_context.cpp b/src/eval_context.cpp index af5947b..7600936 100644 --- a/src/eval_context.cpp +++ b/src/eval_context.cpp @@ -41,6 +41,7 @@ EvalContext EvalContext::childCtx(const oscad::Scope* newScope, std::optionalpush_back(c.get()); EvalContext childCtx = callCtxFor(decl, ctx, childScope, childrenNodes, &ctx); + // callCtx reset this to false; carry the CALLER's value across so + // enterUserCall can tell a forwarded child from a recursive call. + childCtx.viaChildren = ctx.viaChildren; // $children counts module-instantiation child *statements* passed in // `{}`, not the number of geometries they produce -- e.g. children() @@ -712,7 +715,12 @@ Evaluator::UserCallHandle Evaluator::enterUserCall(const std::string& name, cons ++nativeUserCallDepth_; h.countedTowardNativeDepth = true; } - h.prof = profileEnter(isModule ? "module" : "function", name, callPos, &declNode.position()); + // Consumed, not just read: the body's own statements run in this same + // ctx, and a plain call among them is not itself a forwarded child. + const bool viaChildren = childCtx.viaChildren; + childCtx.viaChildren = false; + h.prof = profileEnter(isModule ? (viaChildren ? "child" : "module") : "function", name, callPos, + &declNode.position()); callStack_.push_back(CallStackFrame{kind, name, callPos, &declNode.position(), &declNode, nullptr, upvalueParent}); callStack_.back().bodyCtx = &childCtx; // per-frame locals for the debugger if (isModule) ++moduleCallDepth_; @@ -920,6 +928,11 @@ std::optional Evaluator::prepareChildrenForward(cons // A children() forwarding chain's own dyn/let_/etc. must alias the // *caller's* (not this ctx's) -- see EvalContext::withScope's rationale. EvalContext evalCtx = callerCtx->childCtx(nullptr, std::nullopt, callerCtx->childrenNodes, callerCtx->childrenCallerCtx); + // Everything evaluated from this context is a forwarded child, so a + // module call reached through it profiles as "child" not "module". + // Set here rather than at the returns: there are two of them (bare + // children() and indexed children(i)). + evalCtx.viaChildren = true; // `ctx` here is the post-resolveCallArgs effCtx, deliberately: a // `children($fn=12)`-style named-$ override lives only at effCtx's own // trail level, and TrailView::items() is ancestry-visible, so reading diff --git a/tests/test_profiling.cpp b/tests/test_profiling.cpp index 50528c6..565e4a8 100644 --- a/tests/test_profiling.cpp +++ b/tests/test_profiling.cpp @@ -259,6 +259,47 @@ TEST(ProfilePaths, RootCoversTheProfiledWork) { EXPECT_LE(r.paths[0].cumulativeTime, r.resolveTime + 1e-9); } +// A module reached through children() is kind "child", not "module". +// Both shapes produce a foo->foo edge in the tree, but only one of them is +// recursion, and a profile that cannot tell them apart is misleading. +TEST(Profiling, ChildForwardedCallIsKindChildNotModule) { + const ProfileResult r = profileSrc( + "module recur(x) { cube(1); if (x < 3) recur(x + 1); }\n" + "recur(0);\n" + "module wrap() { children(); }\n" + "wrap() wrap() cube(1);\n"); + + bool sawRecur = false, sawChildWrap = false; + for (const auto& s : r.callSites) { + if (s.name == "recur") { + sawRecur = true; + EXPECT_EQ(s.kind, "module") << "recursion must not be reported as a child"; + } + if (s.name == "wrap" && s.kind == "child") sawChildWrap = true; + } + EXPECT_TRUE(sawRecur) << "fixture produced no recur call site"; + EXPECT_TRUE(sawChildWrap) << "the wrap() handed to wrap() as a child was not kind \"child\""; +} + +// The flag is consumed on entry: a plain call sitting in the body of a +// module that was itself child-forwarded is an ordinary module call. +TEST(Profiling, ChildKindDoesNotLeakIntoTheForwardedBody) { + const ProfileResult r = profileSrc( + "module inner() { sphere(1); }\n" + "module outer() { inner(); children(); }\n" + "module wrap() { children(); }\n" + "wrap() outer() cube(1);\n"); + + bool sawInner = false; + for (const auto& s : r.callSites) { + if (s.name == "inner") { + sawInner = true; + EXPECT_EQ(s.kind, "module") << "a direct call inside a forwarded body is not a child"; + } + } + EXPECT_TRUE(sawInner) << "fixture produced no inner call site"; +} + // Profiling off must cost nothing and produce no tree. TEST(ProfilePaths, NoTreeWhenProfilingIsOff) { Evaluator ev; // profiling off From cd09f9c3b2ef4bae727abec7936ac283f00d0ab8 Mon Sep 17 00:00:00 2001 From: Revar Desmera Date: Thu, 6 Aug 2026 15:37:30 -0700 Subject: [PATCH 3/4] Record the call column, and key call sites by it `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) --- bindings/module.cpp | 5 +++-- include/openscad_cpp_evaluator/evaluator.hpp | 10 ++++++--- include/openscad_cpp_evaluator/profile.hpp | 2 ++ pyproject.toml | 2 +- python/openscad_cpp_evaluator/__init__.py | 3 ++- src/debug_profile.cpp | 19 +++++++++++----- tests/test_cli.cpp | 2 +- tests/test_profiling.cpp | 23 ++++++++++++++++++++ tools/cli/cli_lib.cpp | 13 ++++++----- 9 files changed, 60 insertions(+), 19 deletions(-) diff --git a/bindings/module.cpp b/bindings/module.cpp index 18a83d8..965dd3b 100644 --- a/bindings/module.cpp +++ b/bindings/module.cpp @@ -246,8 +246,8 @@ nb::object profileResultToPy(const std::optional& pr) if (!pr) return nb::none(); nb::list sites; for (const oscadeval::CallSiteProfile& s : pr->callSites) { - sites.append(facadeAttr("CallSiteProfile")(s.kind, s.name, s.callerName, s.callOrigin, s.callLine, s.declOrigin, - s.declLine, s.callCount, s.selfTime, s.cumulativeTime)); + sites.append(facadeAttr("CallSiteProfile")(s.kind, s.name, s.callerName, s.callOrigin, s.callLine, s.callColumn, + s.declOrigin, s.declLine, s.callCount, s.selfTime, s.cumulativeTime)); } // The calling-context tree, as plain dicts. Parent/child INDICES, not // nested objects: the C++ side is already a flat vector keyed that way, @@ -264,6 +264,7 @@ nb::object profileResultToPy(const std::optional& pr) d["name"] = n.name; d["call_origin"] = n.callOrigin; d["call_line"] = n.callLine; + d["call_column"] = n.callColumn; d["decl_origin"] = n.declOrigin; d["decl_line"] = n.declLine; d["call_count"] = n.callCount; diff --git a/include/openscad_cpp_evaluator/evaluator.hpp b/include/openscad_cpp_evaluator/evaluator.hpp index b461a0c..8ce609e 100644 --- a/include/openscad_cpp_evaluator/evaluator.hpp +++ b/include/openscad_cpp_evaluator/evaluator.hpp @@ -1234,12 +1234,16 @@ class Evaluator { // -- Profiling (Phase 9) -------------------------------------------- - // (kind, name, callOrigin, callLine) -- the exact call-site identity a + // (kind, name, callOrigin, callLine, callColumn) -- the exact call-site + // identity a // CallSiteProfile aggregates by. std::map (not unordered_map): a plain // tuple of comparable fields already gets a free operator< from the // standard library, so this needs no custom hash function for a table // that's never more than a few thousand entries even on a large script. - using ProfileSiteKey = std::tuple; + // Column is part of the key, not decoration: `foo() foo();` and + // `f(g(x))` put two distinct call sites on one line, and without it + // they aggregate into one entry whose times belong to neither. + using ProfileSiteKey = std::tuple; // Pushes profiling state for a user module/function call about to // start -- shared by evalUserModule/evalUserFunction/ @@ -1741,7 +1745,7 @@ class Evaluator { // a fresh or sibling child -- the caller must then skip cumulative // time for this entry, exactly as recursiveReentry does for callSites. int profilePathEnter(const std::string& kind, const std::string& name, const std::string& callOrigin, - int callLine, const oscad::Position* declPos, bool& folded); + int callLine, int callColumn, const oscad::Position* declPos, bool& folded); // Fills in every node's cumulativeTime as selfTime + the cumulative of // its children, bottom-up. See profileExit for why this is derived diff --git a/include/openscad_cpp_evaluator/profile.hpp b/include/openscad_cpp_evaluator/profile.hpp index 88b853e..9cbc77c 100644 --- a/include/openscad_cpp_evaluator/profile.hpp +++ b/include/openscad_cpp_evaluator/profile.hpp @@ -18,6 +18,7 @@ struct CallSiteProfile { std::string callerName; // enclosing module/function's own name, or "" std::string callOrigin; int callLine = 0; + int callColumn = 0; // distinguishes two calls sharing one line std::string declOrigin; int declLine = 0; int callCount = 0; @@ -49,6 +50,7 @@ struct ProfilePathNode { std::string name; // callee; "" for the root std::string callOrigin; int callLine = 0; + int callColumn = 0; // distinguishes two calls sharing one line std::string declOrigin; int declLine = 0; int callCount = 0; diff --git a/pyproject.toml b/pyproject.toml index f10a3b9..3a59820 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "scikit_build_core.build" [project] name = "openscad_cpp_evaluator" -version = "0.20.0" +version = "0.21.0" description = "C++ OpenSCAD evaluator with Python bindings" readme = "README.md" requires-python = ">=3.12" diff --git a/python/openscad_cpp_evaluator/__init__.py b/python/openscad_cpp_evaluator/__init__.py index 1e724d0..7f8a2ba 100644 --- a/python/openscad_cpp_evaluator/__init__.py +++ b/python/openscad_cpp_evaluator/__init__.py @@ -142,11 +142,12 @@ def __init__(self, kind, params, bodies, is_builtin, children): class CallSiteProfile: """Aggregated profiling data for one call site. Mirrors the reference's CallSiteProfile -- see ProfileResult's own docstring.""" - kind: str # "module" | "function" + kind: str # "module" | "child" | "function" name: str caller_name: str call_origin: str call_line: int + call_column: int decl_origin: str decl_line: int call_count: int = 0 diff --git a/src/debug_profile.cpp b/src/debug_profile.cpp index 1d9172a..870015b 100644 --- a/src/debug_profile.cpp +++ b/src/debug_profile.cpp @@ -117,7 +117,7 @@ void Evaluator::checkDebug(const oscad::ASTNode& node, EvalContext& ctx, bool fo } int Evaluator::profilePathEnter(const std::string& kind, const std::string& name, const std::string& callOrigin, - int callLine, const oscad::Position* declPos, bool& folded) { + int callLine, int callColumn, const oscad::Position* declPos, bool& folded) { folded = false; if (profilePaths_.empty()) { ProfilePathNode root; @@ -131,14 +131,16 @@ int Evaluator::profilePathEnter(const std::string& kind, const std::string& name // per recursive level (see ProfilePathNode). for (int walk = parent; walk > 0; walk = profilePaths_[static_cast(walk)].parent) { const ProfilePathNode& n = profilePaths_[static_cast(walk)]; - if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && n.kind == kind) { + if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && + n.callColumn == callColumn && n.kind == kind) { folded = true; // recursion: this site is already open on this path return walk; } } for (int childIdx : profilePaths_[static_cast(parent)].children) { const ProfilePathNode& n = profilePaths_[static_cast(childIdx)]; - if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && n.kind == kind) { + if (n.name == name && n.callOrigin == callOrigin && n.callLine == callLine && + n.callColumn == callColumn && n.kind == kind) { return childIdx; } } @@ -153,6 +155,7 @@ int Evaluator::profilePathEnter(const std::string& kind, const std::string& name node.name = name; node.callOrigin = callOrigin; node.callLine = callLine; + node.callColumn = callColumn; node.declOrigin = declPos ? declPos->origin : ""; node.declLine = declPos ? declPos->line : 0; const int idx = static_cast(profilePaths_.size()); @@ -179,7 +182,8 @@ std::optional Evaluator::profileEnter(const std::strin if (!profiling_) return std::nullopt; const std::string callOrigin = callPos ? callPos->origin : ""; const int callLine = callPos ? callPos->line : 0; - const ProfileSiteKey key{kind, name, callOrigin, callLine}; + const int callColumn = callPos ? callPos->column : 0; + const ProfileSiteKey key{kind, name, callOrigin, callLine, callColumn}; auto it = profileSites_.find(key); if (it == profileSites_.end()) { @@ -195,6 +199,7 @@ std::optional Evaluator::profileEnter(const std::strin site.callerName = callStack_.empty() ? "" : callStack_.back().name; site.callOrigin = callOrigin; site.callLine = callLine; + site.callColumn = callColumn; site.declOrigin = declPos ? declPos->origin : ""; site.declLine = declPos ? declPos->line : 0; it = profileSites_.emplace(key, std::move(site)).first; @@ -207,7 +212,7 @@ std::optional Evaluator::profileEnter(const std::strin const int prevPath = profileCurrentPath_; bool folded = false; // only affects node reuse now, not accounting - const int pathNode = profilePathEnter(kind, name, callOrigin, callLine, declPos, folded); + const int pathNode = profilePathEnter(kind, name, callOrigin, callLine, callColumn, declPos, folded); profilePaths_[static_cast(pathNode)].callCount += 1; profileCurrentPath_ = pathNode; @@ -222,7 +227,8 @@ void Evaluator::profileRecordTailHop(const std::string& kind, const std::string& if (!profiling_) return; const std::string callOrigin = callPos ? callPos->origin : ""; const int callLine = callPos ? callPos->line : 0; - const ProfileSiteKey key{kind, name, callOrigin, callLine}; + const int callColumn = callPos ? callPos->column : 0; + const ProfileSiteKey key{kind, name, callOrigin, callLine, callColumn}; auto it = profileSites_.find(key); if (it == profileSites_.end()) { @@ -242,6 +248,7 @@ void Evaluator::profileRecordTailHop(const std::string& kind, const std::string& site.callerName = callStack_.empty() ? "" : callStack_.back().name; site.callOrigin = callOrigin; site.callLine = callLine; + site.callColumn = callColumn; site.declOrigin = declPos ? declPos->origin : ""; site.declLine = declPos ? declPos->line : 0; it = profileSites_.emplace(key, std::move(site)).first; diff --git a/tests/test_cli.cpp b/tests/test_cli.cpp index 792d007..86fe596 100644 --- a/tests/test_cli.cpp +++ b/tests/test_cli.cpp @@ -222,7 +222,7 @@ TEST(CliProfile, CsvFormatWritesHeaderAndCommaSeparatedRows) { 0); const std::string text = readFile(report); EXPECT_NE(text.find("# total_time,"), std::string::npos); - EXPECT_NE(text.find("kind,name,caller,call_origin,call_line,call_count,self_time,cumulative_time\n"), std::string::npos); + EXPECT_NE(text.find("kind,name,caller,call_origin,call_line,call_column,call_count,self_time,cumulative_time\n"), std::string::npos); EXPECT_NE(text.find("function,fib,"), std::string::npos); std::filesystem::remove(src); std::filesystem::remove(out); diff --git a/tests/test_profiling.cpp b/tests/test_profiling.cpp index 565e4a8..4952c86 100644 --- a/tests/test_profiling.cpp +++ b/tests/test_profiling.cpp @@ -259,6 +259,29 @@ TEST(ProfilePaths, RootCoversTheProfiledWork) { EXPECT_LE(r.paths[0].cumulativeTime, r.resolveTime + 1e-9); } +// Two calls to the same module on one line are two call sites. Without +// column in the key they aggregate into one entry whose times and call +// count belong to neither, and the tree shows one row where there are two. +TEST(Profiling, TwoCallsOnOneLineAreSeparateCallSites) { + const ProfileResult r = profileSrc( + "module m() { cube(1); }\n" + "m(); m();\n"); + + std::vector columns; + for (const auto& s : r.callSites) { + if (s.name == "m") { + EXPECT_EQ(s.callLine, 2); + columns.push_back(s.callColumn); + } + } + ASSERT_EQ(columns.size(), 2u) << "the two m() calls on line 2 did not stay separate"; + EXPECT_NE(columns[0], columns[1]) << "both sites reported the same column"; + + size_t mNodes = 0; + for (const auto& n : r.paths) if (n.name == "m") ++mNodes; + EXPECT_EQ(mNodes, 2u) << "the call tree collapsed both calls onto one node"; +} + // A module reached through children() is kind "child", not "module". // Both shapes produce a foo->foo edge in the tree, but only one of them is // recursion, and a profile that cannot tell them apart is misleading. diff --git a/tools/cli/cli_lib.cpp b/tools/cli/cli_lib.cpp index 0e2bad3..626a0b4 100644 --- a/tools/cli/cli_lib.cpp +++ b/tools/cli/cli_lib.cpp @@ -47,7 +47,7 @@ struct ProfileOptions { // Filters profile.callSites to selfTime >= minSelf and callCount >= // minCalls, then sorts by opts.sortKey. Every non-"name" order is -// tie-broken by (callOrigin, callLine, name) -- CallSiteProfile's own +// tie-broken by (callOrigin, callLine, callColumn, name) -- CallSiteProfile's own // storage order (a std::map's key order) isn't sorted by any of these, so // this needs an explicit, deterministic tie-break regardless of sort key. // Ported identically to the Python reference's own @@ -61,6 +61,7 @@ std::vector selectAndSortCallSites(const ProfileResult& profile auto tieBreak = [](const CallSiteProfile& a, const CallSiteProfile& b) { if (a.callOrigin != b.callOrigin) return a.callOrigin < b.callOrigin; if (a.callLine != b.callLine) return a.callLine < b.callLine; + if (a.callColumn != b.callColumn) return a.callColumn < b.callColumn; return a.name < b.name; }; if (opts.sortKey == "cumulative") { @@ -75,7 +76,8 @@ std::vector selectAndSortCallSites(const ProfileResult& profile std::sort(sites.begin(), sites.end(), [](const CallSiteProfile& a, const CallSiteProfile& b) { if (a.name != b.name) return a.name < b.name; if (a.callOrigin != b.callOrigin) return a.callOrigin < b.callOrigin; - return a.callLine < b.callLine; + if (a.callLine != b.callLine) return a.callLine < b.callLine; + return a.callColumn < b.callColumn; }); } else { // "self" (default) std::sort(sites.begin(), sites.end(), [&](const CallSiteProfile& a, const CallSiteProfile& b) { @@ -101,7 +103,8 @@ std::string renderProfileReportText(const std::string& sourcePath, const Profile for (const CallSiteProfile& site : sites) { const std::string& origin = site.callOrigin.empty() ? sourcePath : site.callOrigin; - const std::string location = std::filesystem::path(origin).filename().string() + ":" + std::to_string(site.callLine); + const std::string location = std::filesystem::path(origin).filename().string() + ":" + std::to_string(site.callLine) + ":" + + std::to_string(site.callColumn); out << std::left << std::setw(8) << site.kind << " " << std::setw(24) << site.name << " " << std::setw(24) << site.callerName << " " << std::setw(28) << location << " " << std::right << std::setw(6) << site.callCount << " " << std::setw(12) << std::fixed << std::setprecision(6) << site.selfTime << " " << std::setw(14) @@ -137,11 +140,11 @@ std::string renderProfileReportCsv(const std::string& sourcePath, const ProfileR out << "# resolve_time," << profile.resolveTime << "\n"; out << "# generate_time," << profile.generateTime << "\n"; out << "# unattributed_time," << profile.unattributedTime << "\n"; - out << "kind,name,caller,call_origin,call_line,call_count,self_time,cumulative_time\n"; + out << "kind,name,caller,call_origin,call_line,call_column,call_count,self_time,cumulative_time\n"; for (const CallSiteProfile& site : sites) { const std::string origin = site.callOrigin.empty() ? sourcePath : site.callOrigin; out << csvField(site.kind) << "," << csvField(site.name) << "," << csvField(site.callerName) << "," - << csvField(origin) << "," << site.callLine << "," << site.callCount << "," << std::fixed + << csvField(origin) << "," << site.callLine << "," << site.callColumn << "," << site.callCount << "," << std::fixed << std::setprecision(6) << site.selfTime << "," << std::fixed << std::setprecision(6) << site.cumulativeTime << "\n"; } From 2fc152947d7ffaee76de86559c7c44cd9c893532 Mon Sep 17 00:00:00 2001 From: Revar Desmera Date: Thu, 6 Aug 2026 18:38:32 -0700 Subject: [PATCH 4/4] Keep the profiling fixtures under the native recursion ceiling 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) --- tests/test_profiling.cpp | 22 ++++++++++++++++------ 1 file changed, 16 insertions(+), 6 deletions(-) diff --git a/tests/test_profiling.cpp b/tests/test_profiling.cpp index 4952c86..b09fd93 100644 --- a/tests/test_profiling.cpp +++ b/tests/test_profiling.cpp @@ -158,9 +158,13 @@ const oscadeval::ProfilePathNode* childNamed(const oscadeval::ProfileResult& r, // never "expensive *when called from here*". TEST(ProfilePaths, SameCalleeUnderTwoCallersGetsSeparateNodes) { const ProfileResult r = profileSrc( - "function work(n) = n <= 0 ? 0 : work(n - 1) + 1;\n" - "module light() { x = work(20); cube(1); }\n" - "module heavy() { x = work(400); cube(1); }\n" + // Depth stays under kMaxUserCallDepth (30) -- the native path + // enforces it and only the VM may skip it, so a deeper fixture + // passes with the VM on and dies with it off. The light/heavy + // contrast comes from per-call work, not from depth. + "function work(n) = n <= 0 ? 0 : work(n - 1) + len([for (i = [0:300]) i]);\n" + "module light() { x = work(2); cube(1); }\n" + "module heavy() { x = work(20); cube(1); }\n" "light();\n" "heavy();\n"); ASSERT_FALSE(r.paths.empty()); @@ -194,8 +198,11 @@ TEST(ProfilePaths, SameCalleeUnderTwoCallersGetsSeparateNodes) { // level, or a 400-deep recursion would be 400 nodes. TEST(ProfilePaths, RecursionFoldsOntoASingleNode) { const ProfileResult r = profileSrc( + // 20, not 200: see SameCalleeUnderTwoCallersGetsSeparateNodes on + // kMaxUserCallDepth. Folding is just as visible at this depth -- + // 20 levels still must not become 20 nodes. "function down(n) = n <= 0 ? 0 : down(n - 1) + 1;\n" - "x = down(200);\n" + "x = down(20);\n" "cube(x > 0 ? 1 : 2);\n"); ASSERT_FALSE(r.paths.empty()); size_t downNodes = 0; @@ -224,9 +231,12 @@ TEST(ProfilePaths, RecursionFoldsOntoASingleNode) { // construction. TEST(ProfilePaths, CumulativeTimeContainsChildrenEvenThroughRecursion) { const ProfileResult r = profileSrc( - "function work(n) = n <= 0 ? 0 : work(n - 1) + 1;\n" + // work() is called from inside a module that itself recurses, so + // the two depths ADD -- kMaxUserCallDepth counts the whole native + // stack, not one function's own levels. + "function work(n) = n <= 0 ? 0 : work(n - 1) + len([for (i = [0:200]) i]);\n" "module step(n) {\n" - " x = work(40);\n" + " x = work(8);\n" " cube(1);\n" " if (n > 0) translate([0, 0, 2]) step(n - 1);\n" "}\n"