diff --git a/bindings/module.cpp b/bindings/module.cpp index 71fe9c8..965dd3b 100644 --- a/bindings/module.cpp +++ b/bindings/module.cpp @@ -246,10 +246,34 @@ 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)); } - 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["call_column"] = n.callColumn; + 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/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/evaluator.hpp b/include/openscad_cpp_evaluator/evaluator.hpp index 46d6bb3..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/ @@ -1252,6 +1256,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 +1723,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, 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 + // 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..9cbc77c 100644 --- a/include/openscad_cpp_evaluator/profile.hpp +++ b/include/openscad_cpp_evaluator/profile.hpp @@ -13,11 +13,12 @@ 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; int callLine = 0; + int callColumn = 0; // distinguishes two calls sharing one line std::string declOrigin; int declLine = 0; int callCount = 0; @@ -25,6 +26,38 @@ 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" | "child" | "function"; empty for the root + 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; + 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 +67,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..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.18.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 96ed656..7f8a2ba 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 @@ -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 @@ -165,6 +166,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..870015b 100644 --- a/src/debug_profile.cpp +++ b/src/debug_profile.cpp @@ -116,12 +116,74 @@ 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, int callColumn, 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.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.callColumn == callColumn && 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.callColumn = callColumn; + 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; 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()) { @@ -137,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; @@ -146,7 +209,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, callColumn, 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, @@ -154,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()) { @@ -174,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; @@ -199,6 +274,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/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_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 4235e7f..b09fd93 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,208 @@ 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( + // 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()); + 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( + // 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(20);\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( + // 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(8);\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); +} + +// 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. +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 + 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()); +} 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"; }