From fa6f69f9c5b2d753b7199161ab40ec661f0c190f Mon Sep 17 00:00:00 2001 From: Sergei Zimmerman Date: Fri, 16 May 2025 22:29:18 +0000 Subject: [PATCH] libexpr: Use `EvalProfiler` for `FunctionCallTrace` MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This wires up the {pre,post}FunctionCallHook machinery in EvalState::callFunction and migrates FunctionCallTrace to use the new EvalProfiler mechanisms for tracing. Note that branches when the hook gets called are marked with [[unlikely]] as a hint to the compiler that this is not a hot path. For non-tracing evaluation this should be a 100% predictable branch, so the performance cost is nonexistent. Some measurements to prove support this point: ``` nix build .#nix-cli nix build github:nixos/nix/d692729759e4e370361cc5105fbeb0e33137ca9e#nix-cli --out-link before ``` (Before) ``` $ taskset -c 2,3 hyperfine "GC_INITIAL_HEAP_SIZE=16g before/bin/nix eval nixpkgs#gnome --no-eval-cache" --warmup 4 Benchmark 1: GC_INITIAL_HEAP_SIZE=16g before/bin/nix eval nixpkgs#gnome --no-eval-cache Time (mean ± σ): 2.517 s ± 0.032 s [User: 1.464 s, System: 0.476 s] Range (min … max): 2.464 s … 2.557 s 10 runs ``` (After) ``` $ taskset -c 2,3 hyperfine "GC_INITIAL_HEAP_SIZE=16g result/bin/nix eval nixpkgs#gnome --no-eval-cache" --warmup 4 Benchmark 1: GC_INITIAL_HEAP_SIZE=16g result/bin/nix eval nixpkgs#gnome --no-eval-cache Time (mean ± σ): 2.499 s ± 0.022 s [User: 1.448 s, System: 0.478 s] Range (min … max): 2.472 s … 2.537 s 10 runs ``` --- src/libexpr/eval.cc | 15 +++++++++++--- src/libexpr/function-trace.cc | 12 +++++++---- src/libexpr/include/nix/expr/eval.hh | 4 ++++ .../include/nix/expr/function-trace.hh | 20 +++++++++++++------ 4 files changed, 38 insertions(+), 13 deletions(-) diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index ab7f33d5f..c171caa99 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -372,6 +372,10 @@ EvalState::EvalState( ); createBaseEnv(settings); + + /* Register function call tracer. */ + if (settings.traceFunctionCalls) + profiler.addProfiler(make_ref()); } @@ -1526,9 +1530,14 @@ void EvalState::callFunction(Value & fun, std::span args, Value & vRes, { auto _level = addCallDepth(pos); - auto trace = settings.traceFunctionCalls - ? std::make_unique(positions[pos]) - : nullptr; + auto neededHooks = profiler.getNeededHooks(); + if (neededHooks.test(EvalProfiler::preFunctionCall)) [[unlikely]] + profiler.preFunctionCallHook(*this, fun, args, pos); + + Finally traceExit_{[&](){ + if (profiler.getNeededHooks().test(EvalProfiler::postFunctionCall)) [[unlikely]] + profiler.postFunctionCallHook(*this, fun, args, pos); + }}; forceValue(fun, pos); diff --git a/src/libexpr/function-trace.cc b/src/libexpr/function-trace.cc index 1dce51726..993dd72d7 100644 --- a/src/libexpr/function-trace.cc +++ b/src/libexpr/function-trace.cc @@ -3,16 +3,20 @@ namespace nix { -FunctionCallTrace::FunctionCallTrace(const Pos & pos) : pos(pos) { +void FunctionCallTrace::preFunctionCallHook( + const EvalState & state, const Value & v, std::span args, const PosIdx pos) +{ auto duration = std::chrono::high_resolution_clock::now().time_since_epoch(); auto ns = std::chrono::duration_cast(duration); - printMsg(lvlInfo, "function-trace entered %1% at %2%", pos, ns.count()); + printMsg(lvlInfo, "function-trace entered %1% at %2%", state.positions[pos], ns.count()); } -FunctionCallTrace::~FunctionCallTrace() { +void FunctionCallTrace::postFunctionCallHook( + const EvalState & state, const Value & v, std::span args, const PosIdx pos) +{ auto duration = std::chrono::high_resolution_clock::now().time_since_epoch(); auto ns = std::chrono::duration_cast(duration); - printMsg(lvlInfo, "function-trace exited %1% at %2%", pos, ns.count()); + printMsg(lvlInfo, "function-trace exited %1% at %2%", state.positions[pos], ns.count()); } } diff --git a/src/libexpr/include/nix/expr/eval.hh b/src/libexpr/include/nix/expr/eval.hh index 6a6959bd8..ffbc84bcd 100644 --- a/src/libexpr/include/nix/expr/eval.hh +++ b/src/libexpr/include/nix/expr/eval.hh @@ -3,6 +3,7 @@ #include "nix/expr/attr-set.hh" #include "nix/expr/eval-error.hh" +#include "nix/expr/eval-profiler.hh" #include "nix/util/types.hh" #include "nix/expr/value.hh" #include "nix/expr/nixexpr.hh" @@ -903,6 +904,9 @@ private: typedef std::map FunctionCalls; FunctionCalls functionCalls; + /** Evaluation/call profiler. */ + MultiEvalProfiler profiler; + void incrFunctionCall(ExprLambda * fun); typedef std::map AttrSelects; diff --git a/src/libexpr/include/nix/expr/function-trace.hh b/src/libexpr/include/nix/expr/function-trace.hh index f9b82d8a5..9187cac63 100644 --- a/src/libexpr/include/nix/expr/function-trace.hh +++ b/src/libexpr/include/nix/expr/function-trace.hh @@ -4,14 +4,22 @@ #include "nix/expr/eval.hh" #include "nix/expr/eval-profiler.hh" -#include - namespace nix { -struct FunctionCallTrace +class FunctionCallTrace : public EvalProfiler { - const Pos pos; - FunctionCallTrace(const Pos & pos); - ~FunctionCallTrace(); + Hooks getNeededHooksImpl() const override + { + return Hooks().set(preFunctionCall).set(postFunctionCall); + } + +public: + FunctionCallTrace() = default; + + [[gnu::noinline]] void + preFunctionCallHook(const EvalState & state, const Value & v, std::span args, const PosIdx pos) override; + [[gnu::noinline]] void + postFunctionCallHook(const EvalState & state, const Value & v, std::span args, const PosIdx pos) override; }; + }