From 7ded48d23a7aa2dff1949a143f6be289d8a8184d Mon Sep 17 00:00:00 2001 From: Revar Desmera Date: Tue, 6 Oct 2026 09:09:22 -0700 Subject: [PATCH] profile_time(): time a block's script and geometry, or an expression profile_time([label]) { ... } prints PROFILE: label: T (script S, geometry G) and x = profile_time([label]) expr; prints PROFILE: label: T and evaluates to expr's value. Times under 1 ms print in microseconds. Script time is taken around the resolve call in evalModularCall and kept on CSGNode::profileScriptMs, outside cacheKey() so profiling never defeats the ManifoldCache. Geometry time is taken in generateTreeImpl from before the cache lookup, so a hit reports 'geometry cached'; a hit on an ancestor walks its subtree for profile_time() nodes (only when the run has any). A resolve-only run reports script time alone. The expression form is interpreter-only (NotCompilable) and kept out of simplifyTailStep so the clock stops after the body. PROFILE lines go straight to the echo callback, never into cached warnings. supported_feature("profile-time") is 1. Parser: openscad_cpp_parser #14 (submodule bumped to it). Co-Authored-By: Claude Opus 5.5 --- CLAUDE.md | 30 ++++ external/openscad_cpp_parser | 2 +- include/openscad_cpp_evaluator/csg_node.hpp | 7 + include/openscad_cpp_evaluator/evaluator.hpp | 17 +++ src/CMakeLists.txt | 1 + src/builtins/builtins.hpp | 6 + src/builtins/function_builtins.cpp | 1 + src/builtins/profile_time.cpp | 63 +++++++++ src/builtins/registry.cpp | 2 + src/coverage.cpp | 6 + src/csg_generate.cpp | 11 ++ src/csg_resolve.cpp | 19 +++ src/expr_eval.cpp | 15 ++ src/format_closure.cpp | 4 + tests/CMakeLists.txt | 1 + tests/test_profile_time.cpp | 139 +++++++++++++++++++ 16 files changed, 323 insertions(+), 1 deletion(-) create mode 100644 src/builtins/profile_time.cpp create mode 100644 tests/test_profile_time.cpp diff --git a/CLAUDE.md b/CLAUDE.md index 75b8491..250eee8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -1866,3 +1866,33 @@ A compiled function keeps its parameters in frame slots, which no `EvalContext` can see, and the children are statement opcodes that resolve names through the context — without this, `function f(w) = render() { cube(w); }.volume;` finds no `w` and silently measures nothing. + +## `profile_time()` + +`profile_time([label]) { ... }` prints `PROFILE: label: T ms (script S ms, geometry G ms)`; +`x = profile_time([label]) expr;` prints `PROFILE: label: T ms` and evaluates to `expr`'s value. +`supported_feature("profile-time")` is 1. The label is optional (default `line N of file`), and +is evaluated before the clock starts. Times under 1 ms print in microseconds (`fmtMs`), so a fast part never reads `0.00 ms`. + +### Implementation notes + +- **Parser:** `profile_time` is a reserved keyword (`KW_PROFILE_TIME`) for the same reason as + `render`. The statement form is a plain `ModularCall` named `profile_time`; the expression form + is a `ProfileTimeOp` node shaped like `EchoOp`, with a required body. +- **Script time** is taken around the resolve function's call in `Evaluator::evalModularCall` + (csg_resolve.cpp), not inside `resolveProfileTime`, so argument evaluation and every child + count. It is stored on `CSGNode::profileScriptMs`, which is deliberately not in `cacheKey()` -- + a timing in the key would make every profiled subtree a permanent miss. +- **Geometry time** is taken in `generateTreeImpl`, from *before* the cache lookup, and printed + when the node finishes, so a hit reports `geometry cached` rather than vanishing. A hit on an + **ancestor** never visits the profile_time() node at all; `reportCachedProfiles` walks the hit + subtree for them, but only when the run resolved any (`profileNodeCount_`), so a model without + profile_time() pays nothing on its hits. +- **Resolve-only runs** (`evaluate(..., generate=false)`) print `script S ms (no geometry built)` + at resolve time instead (`generateRequested_`). +- **Expression form** is interpreter-only: the bytecode compiler has no case for + `ProfileTimeOp`, so its `default:` throws `NotCompilable` and the containing function falls back + to the interpreter. It is also deliberately absent from `simplifyTailStep` -- the clock must stop + after the body, which a tail step would not wait for. +- `PROFILE:` lines go straight to `echoFn_`, not through `emitWarning`, so the ManifoldCache never + stores or replays them (a replay would print a stale time as if it were current). diff --git a/external/openscad_cpp_parser b/external/openscad_cpp_parser index aa81dc1..ec14be0 160000 --- a/external/openscad_cpp_parser +++ b/external/openscad_cpp_parser @@ -1 +1 @@ -Subproject commit aa81dc14cdbe8d7769048b9ed75cb2b4d0d37bbc +Subproject commit ec14be07ab667ec21d284a44767aba7e7b536035 diff --git a/include/openscad_cpp_evaluator/csg_node.hpp b/include/openscad_cpp_evaluator/csg_node.hpp index c4132a7..a84a59b 100644 --- a/include/openscad_cpp_evaluator/csg_node.hpp +++ b/include/openscad_cpp_evaluator/csg_node.hpp @@ -71,6 +71,13 @@ struct CSGNode { // stack risk the moment this node is ever destroyed. int treeDepth = 1; + // profile_time() only: how long resolving this node (its arguments and + // its children's script code) took, in ms; < 0 for every other node. + // Measured fresh on every run, so -- like warnEntry -- deliberately NOT + // part of cacheKey(): putting a timing in the key would make every + // profiled subtree a permanent cache miss. + double profileScriptMs = -1.0; + // Memoizes manifold_cache.cpp's cacheKey(*this) -- that function // recurses into every descendant to build its own key, so without this // memo a generate-time walk that calls cacheKey() at every node (not diff --git a/include/openscad_cpp_evaluator/evaluator.hpp b/include/openscad_cpp_evaluator/evaluator.hpp index 577fc3e..d21a307 100644 --- a/include/openscad_cpp_evaluator/evaluator.hpp +++ b/include/openscad_cpp_evaluator/evaluator.hpp @@ -422,6 +422,22 @@ class Evaluator { // subtree, not just direct children, since hull() consumes all of it. bool insideHull = false; + // profile_time(). generateRequested_ is false only inside an + // evaluate(generate = false) run, where no geometry pass follows to + // report a profiled block, so resolve reports the script time alone. + // profileNodeCount_ counts this run's profile_time() nodes so a cache + // hit only walks its subtree for them when there are any (see + // reportCachedProfiles). + bool generateRequested_ = true; + std::size_t profileNodeCount_ = 0; + // Prints "PROFILE: