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: