profile_time(): time a block's script and geometry, or an expression

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).

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

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: <label>: ..." for a profile_time() node. geometryMs
+    // < 0 means no geometry pass; `cached` means its geometry came from the
+    // ManifoldCache rather than being built.
+    void reportProfile(const CSGNode& node, double geometryMs, bool cached);
+    // A cache hit at `node` skips its whole subtree, so a profile_time()
+    // inside it would otherwise print nothing at all.
+    void reportCachedProfiles(const CSGNode& node);
+
     ColoredBody tagGenerated(manifold::Manifold body, const oscad::ASTNode& node, const Value& colorValue);
 
     // tagGenerated()'s counterpart for a mesh Manifold refused to build --
@@ -837,6 +853,7 @@ class Evaluator {
     Value evalLetExpr(const oscad::LetOp& node, EvalContext& ctx);
     Value evalEchoExpr(const oscad::EchoOp& node, EvalContext& ctx);
     Value evalAssertExpr(const oscad::AssertOp& node, EvalContext& ctx);
+    Value evalProfileTimeExpr(const oscad::ProfileTimeOp& node, EvalContext& ctx);
     void bindLetName(EvalContext& ctx, const std::string& name, const Value& v);
 
     // Bracketed public in place: Stage 2's Op::NativeStatement

src/CMakeLists.txt

@@ -43,6 +43,7 @@ add_library(openscad_cpp_evaluator STATIC
   builtins/booleans.cpp
   builtins/modifiers.cpp
   builtins/control.cpp
+  builtins/profile_time.cpp
   builtins/function_builtins.cpp
   builtins/import.cpp
   builtins/topology.cpp

src/builtins/builtins.hpp

@@ -146,6 +146,12 @@ std::vector<ColoredBody> generateChildren(Evaluator& ev, const CSGParams& params
 // generateTree()'s default child-concatenation, exactly reproducing
 // passthrough).
 CSGParams resolveRender(Evaluator& ev, const oscad::ModularCall& node, EvalContext& ctx);
+CSGParams resolveProfileTime(Evaluator& ev, const oscad::ModularCall& node, EvalContext& ctx);
+// profile_time()'s message pieces: "12.40 ms" (or "4.7 µs" under 1 ms), and the label it names --
+// the label as written (a non-string formatted like echo() would), or
+// "line N" (with the file when there is one) when none was given.
+std::string fmtMs(double ms);
+std::string profileLabel(const Value& label, const oscad::Position& pos);
 
 // breakpoint() -- no-op as of Phase 4 (no debugger until Phase 9); still
 // evaluates/validates its optional `condition` argument for parity.

src/builtins/function_builtins.cpp

@@ -1018,6 +1018,7 @@ const std::unordered_map<std::string, double>& featureLevels() {
         {"roof-op", 1.0},            // roof(), method="voronoi" only
         {"svg-class", 1.0},          // import(svg, class=); id= is upstream's
         {"discretization-by-error", 1.0}, // $fe, always on (upstream: behind --enable)
+        {"profile-time", 1.0},       // profile_time(label) { ... } and profile_time(label) expr
     };
     return levels;
 }

src/builtins/profile_time.cpp

@@ -0,0 +1,63 @@
+#include "builtins.hpp"
+
+#include "openscad_cpp_evaluator/call_args.hpp"
+#include "openscad_cpp_evaluator/evaluator.hpp"
+
+#include <cstdio>
+
+namespace oscadeval {
+
+// Microseconds below a millisecond, where "0.00 ms" would hide the answer.
+std::string fmtMs(double ms) {
+    char buf[32];
+    if (ms < 1.0) std::snprintf(buf, sizeof buf, "%.1f \u00b5s", ms * 1000.0);
+    else std::snprintf(buf, sizeof buf, "%.2f ms", ms);
+    return buf;
+}
+
+std::string profileLabel(const Value& label, const oscad::Position& pos) {
+    if (const std::string* s = std::get_if<std::string>(&label)) return *s;
+    if (!std::holds_alternative<std::monostate>(label)) return fmtValue(label);
+    std::string where = "line " + std::to_string(pos.line);
+    if (!pos.origin.empty()) where += " of " + pos.origin.substr(pos.origin.find_last_of("/\\") + 1);
+    return where;
+}
+
+// profile_time([label]) { ... } -- resolves its children like render() does.
+// The script-time clock is NOT here but around this call in
+// Evaluator::evalModularCall, so it covers argument evaluation and every
+// child alike; the geometry time is taken in generateTreeImpl. The label
+// goes into params (it is constant, so it costs the cache nothing).
+CSGParams resolveProfileTime(Evaluator& ev, const oscad::ModularCall& node, EvalContext& ctx) {
+    auto [args, effCtx] = resolveCallArgs(ev, node.arguments, ctx);
+    CSGParams params;
+    params["label"] = getArg(args, 0, "label");
+    EvalContext blockCtx = ev.blockScope(effCtx);
+    ev.evalChildren(node.children, blockCtx);
+    return params;
+}
+
+void Evaluator::reportProfile(const CSGNode& node, double geometryMs, bool cached) {
+    if (!echoFn_ || node.node == nullptr) return;
+    auto it = node.params.find("label");
+    const std::string label = profileLabel(it == node.params.end() ? Value{} : it->second, node.node->position());
+    const double scriptMs = node.profileScriptMs < 0 ? 0.0 : node.profileScriptMs;
+    std::string msg = "PROFILE: " + label + ": ";
+    if (geometryMs < 0) {
+        msg += "script " + fmtMs(scriptMs) + " (no geometry built)";
+    } else if (cached) {
+        msg += fmtMs(scriptMs) + " (script " + fmtMs(scriptMs) + ", geometry cached)";
+    } else {
+        msg += fmtMs(scriptMs + geometryMs) + " (script " + fmtMs(scriptMs) + ", geometry " + fmtMs(geometryMs) + ")";
+    }
+    echoFn_(msg);
+}
+
+void Evaluator::reportCachedProfiles(const CSGNode& node) {
+    for (const std::unique_ptr<CSGNode>& c : node.children) {
+        if (c->isBuiltin && c->kind == "profile_time") reportProfile(*c, 0.0, true);
+        reportCachedProfiles(*c);
+    }
+}
+
+} // namespace oscadeval

src/builtins/registry.cpp

@@ -26,6 +26,7 @@ const std::unordered_map<std::string_view, ResolveFn>& resolveDispatch() {
         {"intersection", &resolveCsg},
         {"children", &resolveChildren},
         {"render", &resolveRender},
+        {"profile_time", &resolveProfileTime},
         {"breakpoint", &resolveBreakpoint},
         {"import", &resolveImport},
         {"hull", &resolveHull},
@@ -118,6 +119,7 @@ const std::vector<std::string>* builtinParamNames(const std::string& name) {
         {"minkowski", {"convexity"}},
         {"children", {"index", "separate"}},
         {"render", {"convexity"}},
+        {"profile_time", {"label"}},
         // "repair" and "class" are this port's own additions, not upstream
         // parameters. ("id" IS upstream's, and was declared here long before
         // anything read it -- so a script filtering by id was accepted in

src/coverage.cpp

@@ -263,6 +263,12 @@ class Walker {
                 expr(*o.body);
                 break;
             }
+            case NodeKind::ProfileTimeOp: {
+                auto& o = static_cast<const oscad::ProfileTimeOp&>(e);
+                args(o.arguments);
+                expr(*o.body);
+                break;
+            }
             case NodeKind::FunctionLiteral: {
                 auto& f = static_cast<const oscad::FunctionLiteral&>(e);
                 emit(&e, CoverageKind::Body);

src/csg_generate.cpp

@@ -36,6 +36,10 @@ std::vector<ColoredBody> Evaluator::generateTreeImpl(const std::vector<CSGNode*>
     for (CSGNode* nodePtr : tree) {
         CSGNode& node = *nodePtr;
         checkCancel();
+        // profile_time(): timed from before the cache lookup, so a hit
+        // still reports (as cached) rather than vanishing.
+        const bool profiled = node.isBuiltin && node.kind == "profile_time";
+        const auto profileStart = profiled ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{};
 
         // ManifoldCache lookup: node.uncacheable (rands() taint, set
         // during resolve -- see csg_resolve.cpp) always forces a miss,
@@ -69,6 +73,8 @@ std::vector<ColoredBody> Evaluator::generateTreeImpl(const std::vector<CSGNode*>
             // one (BelfrySCAD #521). Goes through emitWarning so an enclosing
             // capture records them too, exactly as a fresh generate would.
             for (const std::string& w : cached->warnings) emitWarning(w);
+            // A hit skips the subtree, profile_time() calls and all.
+            if (profileNodeCount_ > 0) reportCachedProfiles(node);
             // Skipped entirely while measuring: restampCachedIds writes
             // idToNode/idToColor, and geometry that is about to be discarded
             // has no click-to-source identity worth recording. See
@@ -171,6 +177,11 @@ std::vector<ColoredBody> Evaluator::generateTreeImpl(const std::vector<CSGNode*>
             // capacity, and 35K nodes' worth of 592-byte slots was 230MB.
             for (const std::unique_ptr<CSGNode>& c : node.children) c->bodies = std::vector<ColoredBody>();
         }
+        if (profiled) {
+            reportProfile(node,
+                          std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - profileStart).count(),
+                          cached.has_value());
+        }
         for (const ColoredBody& b : node.bodies) topLevelBodies.push_back(b);
     }
     return topLevelBodies;

src/csg_resolve.cpp

@@ -93,10 +93,17 @@ void Evaluator::evalModularCall(const oscad::ModularCall& node, EvalContext& ctx
     treeStack_.emplace_back();
     const std::uint64_t randsBefore = randsCallCount_;
     CSGParams params;
+    const bool profiled = hasResolveFn && name == "profile_time";
+    double profileScriptMs = -1.0;
     try {
         if (hasResolveFn) {
             warnUnexpectedBuiltinArgs(*this, node);
+            const auto profileStart = profiled ? std::chrono::steady_clock::now() : std::chrono::steady_clock::time_point{};
             params = it->second(*this, node, ctx);
+            if (profiled) {
+                profileScriptMs =
+                    std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - profileStart).count();
+            }
         } else if (!isBuiltin) {
             evalUserModule(static_cast<const oscad::ModuleDeclaration&>(*userModuleDecl), node, ctx);
         } else {
@@ -144,7 +151,13 @@ void Evaluator::evalModularCall(const oscad::ModularCall& node, EvalContext& ctx
     treeNode->uncacheable = uncacheable;
     treeNode->children = std::move(children);
     treeNode->params = std::move(params);
+    treeNode->profileScriptMs = profileScriptMs;
     setTreeDepthOrThrow(*treeNode, node);
+    if (profiled) {
+        ++profileNodeCount_;
+        // No geometry pass will follow to report it, so report it now.
+        if (!generateRequested_) reportProfile(*treeNode, -1.0, false);
+    }
     treeStack_.back().push_back(std::move(treeNode));
 }
 
@@ -271,6 +284,12 @@ std::vector<ColoredBody> Evaluator::evaluateImpl(const NodeList& nodes, EvalCont
 
     using Clock = std::chrono::steady_clock;
     const Clock::time_point resolveStart = profiling_ ? Clock::now() : Clock::time_point{};
+    profileNodeCount_ = 0;
+    generateRequested_ = generate;
+    struct GenerateRequestedGuard {
+        bool& flag;
+        ~GenerateRequestedGuard() { flag = true; }
+    } generateRequestedGuard{generateRequested_};
     std::vector<std::unique_ptr<CSGNode>> tree = resolveTreeImpl(nodes, ctx);
     rerootAtShowOnly(tree);
     const Clock::time_point resolveEnd = profiling_ ? Clock::now() : Clock::time_point{};

src/expr_eval.cpp

@@ -2,6 +2,7 @@
 #include "openscad_cpp_evaluator/utf8.hpp"
 
 #include "openscad_cpp_evaluator/call_args.hpp"
+#include "builtins/builtins.hpp"
 #include "openscad_cpp_evaluator/eval_error.hpp"
 #include "openscad_cpp_evaluator/freetype_font_provider.hpp"
 
@@ -444,6 +445,18 @@ Value Evaluator::evalEchoExpr(const oscad::EchoOp& node, EvalContext& ctx) {
     return evalExpr(*node.body, ctx);
 }
 
+// `x = profile_time("label") expr;` -- times evaluating `expr` and prints
+// it. The label is evaluated before the clock starts, so it isn't counted.
+Value Evaluator::evalProfileTimeExpr(const oscad::ProfileTimeOp& node, EvalContext& ctx) {
+    checkDebug(node, ctx);
+    const Value label = getArg(resolveArgs(*this, node.arguments, ctx), 0, "label");
+    const auto start = std::chrono::steady_clock::now();
+    Value result = evalExpr(*node.body, ctx);
+    const double ms = std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - start).count();
+    if (echoFn_) echoFn_("PROFILE: " + profileLabel(label, node.position()) + ": " + fmtMs(ms));
+    return result;
+}
+
 Value Evaluator::evalAssertExpr(const oscad::AssertOp& node, EvalContext& ctx) {
     // Unlike the statement form (evalAssertStatement), which supports named
     // arguments via getArg()/CallArgs, the expression form indexes raw
@@ -518,6 +531,8 @@ Value Evaluator::evalExpr(const oscad::Expression& node, EvalContext& ctx) {
             return evalEchoExpr(static_cast<const oscad::EchoOp&>(node), ctx);
         case NodeKind::AssertOp:
             return evalAssertExpr(static_cast<const oscad::AssertOp&>(node), ctx);
+        case NodeKind::ProfileTimeOp:
+            return evalProfileTimeExpr(static_cast<const oscad::ProfileTimeOp&>(node), ctx);
 
         case NodeKind::PrimaryIndex: {
             auto& n = static_cast<const oscad::PrimaryIndex&>(node);

src/format_closure.cpp

@@ -163,6 +163,10 @@ std::string fmt(const ASTNode& n) {
         const auto& a = static_cast<const oscad::AssertOp&>(n);
         return "assert(" + join(a.arguments, ", ") + ") " + fmt(*a.body);
     }
+    case NodeKind::ProfileTimeOp: {
+        const auto& p = static_cast<const oscad::ProfileTimeOp&>(n);
+        return "profile_time(" + join(p.arguments, ", ") + ") " + fmt(*p.body);
+    }
 
     case NodeKind::ListComprehension: {
         const auto& c = static_cast<const oscad::ListComprehension&>(n);

tests/CMakeLists.txt

@@ -19,6 +19,7 @@ add_executable(oscad_eval_tests
   test_primitives.cpp
   test_transforms.cpp
   test_render_expr.cpp
+  test_profile_time.cpp
   test_booleans.cpp
   test_children_separate.cpp
   test_feature_detection.cpp