libexpr: Include derivation names in the call stack profile

src/libexpr/eval-profiler.cc

@@ -5,18 +5,14 @@
 
 namespace nix {
 
-void EvalProfiler::preFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
-{
-}
+void EvalProfiler::preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) {}
 
-void EvalProfiler::postFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+void EvalProfiler::postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
 }
 
 void MultiEvalProfiler::preFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+    EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
     for (auto & profiler : profilers) {
         if (profiler->getNeededHooks().test(Hook::preFunctionCall))
@@ -25,7 +21,7 @@ void MultiEvalProfiler::preFunctionCallHook(
 }
 
 void MultiEvalProfiler::postFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+    EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
     for (auto & profiler : profilers) {
         if (profiler->getNeededHooks().test(Hook::postFunctionCall))
@@ -99,6 +95,14 @@ struct FunctorFrameInfo
     auto operator<=>(const FunctorFrameInfo & rhs) const = default;
 };
 
+struct DerivationStrictFrameInfo
+{
+    PosIdx callPos = noPos;
+    std::string drvName;
+    std::ostream & symbolize(const EvalState & state, std::ostream & os, PosCache & posCache) const;
+    auto operator<=>(const DerivationStrictFrameInfo & rhs) const = default;
+};
+
 /** Fallback frame info. */
 struct GenericFrameInfo
 {
@@ -107,7 +111,8 @@ struct GenericFrameInfo
     auto operator<=>(const GenericFrameInfo & rhs) const = default;
 };
 
-using FrameInfo = std::variant<LambdaFrameInfo, PrimOpFrameInfo, FunctorFrameInfo, GenericFrameInfo>;
+using FrameInfo =
+    std::variant<LambdaFrameInfo, PrimOpFrameInfo, FunctorFrameInfo, DerivationStrictFrameInfo, GenericFrameInfo>;
 using FrameStack = std::vector<FrameInfo>;
 
 /**
@@ -125,8 +130,10 @@ class SampleStack : public EvalProfiler
         return Hooks().set(preFunctionCall).set(postFunctionCall);
     }
 
+    FrameInfo getPrimOpFrameInfo(const PrimOp & primOp, std::span<Value *> args, PosIdx pos);
+
 public:
-    SampleStack(const EvalState & state, std::filesystem::path profileFile, std::chrono::nanoseconds period)
+    SampleStack(EvalState & state, std::filesystem::path profileFile, std::chrono::nanoseconds period)
         : state(state)
         , sampleInterval(period)
         , profileFd([&]() {
@@ -140,23 +147,22 @@ class SampleStack : public EvalProfiler
     }
 
     [[gnu::noinline]] void
-    preFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
     [[gnu::noinline]] void
-    postFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
 
     void maybeSaveProfile(std::chrono::time_point<std::chrono::high_resolution_clock> now);
     void saveProfile();
-    FrameInfo getFrameInfoFromValueAndPos(const Value & v, PosIdx pos);
+    FrameInfo getFrameInfoFromValueAndPos(const Value & v, std::span<Value *> args, PosIdx pos);
 
     SampleStack(SampleStack &&) = default;
     SampleStack & operator=(SampleStack &&) = delete;
     SampleStack(const SampleStack &) = delete;
     SampleStack & operator=(const SampleStack &) = delete;
     ~SampleStack();
-
 private:
     /** Hold on to an instance of EvalState for symbolizing positions. */
-    const EvalState & state;
+    EvalState & state;
     std::chrono::nanoseconds sampleInterval;
     AutoCloseFD profileFd;
     FrameStack stack;
@@ -167,15 +173,41 @@ class SampleStack : public EvalProfiler
     PosCache posCache;
 };
 
-FrameInfo SampleStack::getFrameInfoFromValueAndPos(const Value & v, PosIdx pos)
+FrameInfo SampleStack::getPrimOpFrameInfo(const PrimOp & primOp, std::span<Value *> args, PosIdx pos)
+{
+    auto derivationInfo = [&]() -> std::optional<FrameInfo> {
+        /* Here we rely a bit on the implementation details of libexpr/primops/derivation.nix
+           and derivationStrict primop. This is not ideal, but is necessary for
+           the usefulness of the profiler. This might actually affect the evaluation,
+           but the cost shouldn't be that high as to make the traces entirely inaccurate. */
+        if (primOp.name == "derivationStrict") {
+            try {
+                /* Error context strings don't actually matter, since we ignore all eval errors. */
+                state.forceAttrs(*args[0], pos, "");
+                auto attrs = args[0]->attrs();
+                auto nameAttr = state.getAttr(state.sName, attrs, "");
+                auto drvName = std::string(state.forceStringNoCtx(*nameAttr->value, pos, ""));
+                return DerivationStrictFrameInfo{.callPos = pos, .drvName = std::move(drvName)};
+            } catch (...) {
+                /* Ignore all errors, since those will be diagnosed by the evaluator itself. */
+            }
+        }
+
+        return std::nullopt;
+    }();
+
+    return derivationInfo.value_or(PrimOpFrameInfo{.expr = &primOp, .callPos = pos});
+}
+
+FrameInfo SampleStack::getFrameInfoFromValueAndPos(const Value & v, std::span<Value *> args, PosIdx pos)
 {
     /* NOTE: No actual references to garbage collected values are not held in
        the profiler. */
     if (v.isLambda())
         return LambdaFrameInfo{.expr = v.payload.lambda.fun, .callPos = pos};
-    else if (v.isPrimOp())
-        return PrimOpFrameInfo{.expr = v.primOp(), .callPos = pos};
-    else if (v.isPrimOpApp())
+    else if (v.isPrimOp()) {
+        return getPrimOpFrameInfo(*v.primOp(), args, pos);
+    } else if (v.isPrimOpApp())
         /* Resolve primOp eagerly. Must not hold on to a reference to a Value. */
         return PrimOpFrameInfo{.expr = v.primOpAppPrimOp(), .callPos = pos};
     else if (state.isFunctor(v)) {
@@ -190,10 +222,10 @@ FrameInfo SampleStack::getFrameInfoFromValueAndPos(const Value & v, PosIdx pos)
         return GenericFrameInfo{.pos = pos};
 }
 
-[[gnu::noinline]] void SampleStack::preFunctionCallHook(
-    const EvalState & state, const Value & v, [[maybe_unused]] std::span<Value *> args, const PosIdx pos)
+[[gnu::noinline]] void
+SampleStack::preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
-    stack.push_back(getFrameInfoFromValueAndPos(v, pos));
+    stack.push_back(getFrameInfoFromValueAndPos(v, args, pos));
 
     auto now = std::chrono::high_resolution_clock::now();
 
@@ -208,9 +240,8 @@ FrameInfo SampleStack::getFrameInfoFromValueAndPos(const Value & v, PosIdx pos)
 }
 
 [[gnu::noinline]] void
-SampleStack::postFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+SampleStack::postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
-
     if (!stack.empty())
         stack.pop_back();
 }
@@ -251,6 +282,18 @@ std::ostream & PrimOpFrameInfo::symbolize(const EvalState & state, std::ostream
     return os;
 }
 
+std::ostream &
+DerivationStrictFrameInfo::symbolize(const EvalState & state, std::ostream & os, PosCache & posCache) const
+{
+    /* Sometimes callsite position can have an unresolved origin, which
+       leads to confusing «none»:0 locations in the profile. */
+    auto pos = posCache.lookup(callPos);
+    if (!std::holds_alternative<std::monostate>(pos.origin))
+        os << posCache.lookup(callPos) << ":";
+    os << "primop derivationStrict:" << drvName;
+    return os;
+}
+
 void SampleStack::maybeSaveProfile(std::chrono::time_point<std::chrono::high_resolution_clock> now)
 {
     if (now - lastDump >= profileDumpInterval)
@@ -300,8 +343,7 @@ SampleStack::~SampleStack()
 
 } // namespace
 
-ref<EvalProfiler>
-makeSampleStackProfiler(const EvalState & state, std::filesystem::path profileFile, uint64_t frequency)
+ref<EvalProfiler> makeSampleStackProfiler(EvalState & state, std::filesystem::path profileFile, uint64_t frequency)
 {
     /* 0 is a special value for sampling stack after each call. */
     std::chrono::nanoseconds period = frequency == 0

src/libexpr/eval.cc

@@ -2243,6 +2243,16 @@ bool EvalState::forceBool(Value & v, const PosIdx pos, std::string_view errorCtx
     return v.boolean();
 }
 
+Bindings::const_iterator EvalState::getAttr(Symbol attrSym, const Bindings * attrSet, std::string_view errorCtx)
+{
+    auto value = attrSet->find(attrSym);
+    if (value == attrSet->end()) {
+        error<TypeError>("attribute '%s' missing", symbols[attrSym])
+            .withTrace(noPos, errorCtx)
+            .debugThrow();
+    }
+    return value;
+}
 
 bool EvalState::isFunctor(const Value & fun) const
 {

src/libexpr/function-trace.cc

@@ -4,15 +4,15 @@
 namespace nix {
 
 void FunctionCallTrace::preFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+    EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
     auto duration = std::chrono::high_resolution_clock::now().time_since_epoch();
     auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(duration);
     printMsg(lvlInfo, "function-trace entered %1% at %2%", state.positions[pos], ns.count());
 }
 
 void FunctionCallTrace::postFunctionCallHook(
-    const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
+    EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos)
 {
     auto duration = std::chrono::high_resolution_clock::now().time_since_epoch();
     auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(duration);

src/libexpr/include/nix/expr/eval-profiler.hh

@@ -62,8 +62,7 @@ public:
      * @param args Function arguments.
      * @param pos Function position.
      */
-    virtual void
-    preFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos);
+    virtual void preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos);
 
     /**
      * Hook called on EvalState::callFunction exit.
@@ -74,8 +73,7 @@ public:
      * @param args Function arguments.
      * @param pos Function position.
      */
-    virtual void
-    postFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos);
+    virtual void postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos);
 
     virtual ~EvalProfiler() = default;
 
@@ -106,12 +104,11 @@ public:
     void addProfiler(ref<EvalProfiler> profiler);
 
     [[gnu::noinline]] void
-    preFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
     [[gnu::noinline]] void
-    postFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
 };
 
-ref<EvalProfiler>
-makeSampleStackProfiler(const EvalState & state, std::filesystem::path profileFile, uint64_t frequency);
+ref<EvalProfiler> makeSampleStackProfiler(EvalState & state, std::filesystem::path profileFile, uint64_t frequency);
 
 }

src/libexpr/include/nix/expr/eval.hh

@@ -542,6 +542,11 @@ public:
     std::string_view forceString(Value & v, NixStringContext & context, const PosIdx pos, std::string_view errorCtx, const ExperimentalFeatureSettings & xpSettings = experimentalFeatureSettings);
     std::string_view forceStringNoCtx(Value & v, const PosIdx pos, std::string_view errorCtx);
 
+    /**
+     * Get attribute from an attribute set and throw an error if it doesn't exist.
+     */
+    Bindings::const_iterator getAttr(Symbol attrSym, const Bindings * attrSet, std::string_view errorCtx);
+
     template<typename... Args>
     [[gnu::noinline]]
     void addErrorTrace(Error & e, const Args & ... formatArgs) const;

src/libexpr/include/nix/expr/function-trace.hh

@@ -17,9 +17,9 @@ public:
     FunctionCallTrace() = default;
 
     [[gnu::noinline]] void
-    preFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    preFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
     [[gnu::noinline]] void
-    postFunctionCallHook(const EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
+    postFunctionCallHook(EvalState & state, const Value & v, std::span<Value *> args, const PosIdx pos) override;
 };
 
 }

src/libexpr/primops.cc

@@ -670,26 +670,12 @@ struct CompareValues
 
 typedef std::list<Value *, gc_allocator<Value *>> ValueList;
 
-
-static Bindings::const_iterator getAttr(
-    EvalState & state,
-    Symbol attrSym,
-    const Bindings * attrSet,
-    std::string_view errorCtx)
-{
-    auto value = attrSet->find(attrSym);
-    if (value == attrSet->end()) {
-        state.error<TypeError>("attribute '%s' missing", state.symbols[attrSym]).withTrace(noPos, errorCtx).debugThrow();
-    }
-    return value;
-}
-
 static void prim_genericClosure(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
     state.forceAttrs(*args[0], noPos, "while evaluating the first argument passed to builtins.genericClosure");
 
     /* Get the start set. */
-    auto startSet = getAttr(state, state.sStartSet, args[0]->attrs(), "in the attrset passed as argument to builtins.genericClosure");
+    auto startSet = state.getAttr(state.sStartSet, args[0]->attrs(), "in the attrset passed as argument to builtins.genericClosure");
 
     state.forceList(*startSet->value, noPos, "while evaluating the 'startSet' attribute passed as argument to builtins.genericClosure");
 
@@ -703,7 +689,7 @@ static void prim_genericClosure(EvalState & state, const PosIdx pos, Value * * a
     }
 
     /* Get the operator. */
-    auto op = getAttr(state, state.sOperator, args[0]->attrs(), "in the attrset passed as argument to builtins.genericClosure");
+    auto op = state.getAttr(state.sOperator, args[0]->attrs(), "in the attrset passed as argument to builtins.genericClosure");
     state.forceFunction(*op->value, noPos, "while evaluating the 'operator' attribute passed as argument to builtins.genericClosure");
 
     /* Construct the closure by applying the operator to elements of
@@ -720,7 +706,7 @@ static void prim_genericClosure(EvalState & state, const PosIdx pos, Value * * a
 
         state.forceAttrs(*e, noPos, "while evaluating one of the elements generated by (or initially passed to) builtins.genericClosure");
 
-        auto key = getAttr(state, state.sKey, e->attrs(), "in one of the attrsets generated by (or initially passed to) builtins.genericClosure");
+        auto key = state.getAttr(state.sKey, e->attrs(), "in one of the attrsets generated by (or initially passed to) builtins.genericClosure");
         state.forceValue(*key->value, noPos);
 
         if (!doneKeys.insert(key->value).second) continue;
@@ -1203,7 +1189,7 @@ static void prim_derivationStrict(EvalState & state, const PosIdx pos, Value * *
     auto attrs = args[0]->attrs();
 
     /* Figure out the name first (for stack backtraces). */
-    auto nameAttr = getAttr(state, state.sName, attrs, "in the attrset passed as argument to builtins.derivationStrict");
+    auto nameAttr = state.getAttr(state.sName, attrs, "in the attrset passed as argument to builtins.derivationStrict");
 
     std::string drvName;
     try {
@@ -1893,7 +1879,7 @@ static void prim_findFile(EvalState & state, const PosIdx pos, Value * * args, V
         if (i != v2->attrs()->end())
             prefix = state.forceStringNoCtx(*i->value, pos, "while evaluating the `prefix` attribute of an element of the list passed to builtins.findFile");
 
-        i = getAttr(state, state.sPath, v2->attrs(), "in an element of the __nixPath");
+        i = state.getAttr(state.sPath, v2->attrs(), "in an element of the __nixPath");
 
         NixStringContext context;
         auto path = state.coerceToString(pos, *i->value, context,
@@ -2782,8 +2768,7 @@ void prim_getAttr(EvalState & state, const PosIdx pos, Value * * args, Value & v
 {
     auto attr = state.forceStringNoCtx(*args[0], pos, "while evaluating the first argument passed to builtins.getAttr");
     state.forceAttrs(*args[1], pos, "while evaluating the second argument passed to builtins.getAttr");
-    auto i = getAttr(
-        state,
+    auto i = state.getAttr(
         state.symbols.create(attr),
         args[1]->attrs(),
         "in the attribute set under consideration"
@@ -2973,13 +2958,13 @@ static void prim_listToAttrs(EvalState & state, const PosIdx pos, Value * * args
     for (auto v2 : args[0]->listItems()) {
         state.forceAttrs(*v2, pos, "while evaluating an element of the list passed to builtins.listToAttrs");
 
-        auto j = getAttr(state, state.sName, v2->attrs(), "in a {name=...; value=...;} pair");
+        auto j = state.getAttr(state.sName, v2->attrs(), "in a {name=...; value=...;} pair");
 
         auto name = state.forceStringNoCtx(*j->value, j->pos, "while evaluating the `name` attribute of an element of the list passed to builtins.listToAttrs");
 
         auto sym = state.symbols.create(name);
         if (seen.insert(sym).second) {
-            auto j2 = getAttr(state, state.sValue, v2->attrs(), "in a {name=...; value=...;} pair");
+            auto j2 = state.getAttr(state.sValue, v2->attrs(), "in a {name=...; value=...;} pair");
             attrs.insert(sym, j2->value, j2->pos);
         }
     }
@@ -4224,15 +4209,15 @@ static void prim_convertHash(EvalState & state, const PosIdx pos, Value * * args
     state.forceAttrs(*args[0], pos, "while evaluating the first argument passed to builtins.convertHash");
     auto inputAttrs = args[0]->attrs();
 
-    auto iteratorHash = getAttr(state, state.symbols.create("hash"), inputAttrs, "while locating the attribute 'hash'");
+    auto iteratorHash = state.getAttr(state.symbols.create("hash"), inputAttrs, "while locating the attribute 'hash'");
     auto hash = state.forceStringNoCtx(*iteratorHash->value, pos, "while evaluating the attribute 'hash'");
 
     auto iteratorHashAlgo = inputAttrs->get(state.symbols.create("hashAlgo"));
     std::optional<HashAlgorithm> ha = std::nullopt;
     if (iteratorHashAlgo)
         ha = parseHashAlgo(state.forceStringNoCtx(*iteratorHashAlgo->value, pos, "while evaluating the attribute 'hashAlgo'"));
 
-    auto iteratorToHashFormat = getAttr(state, state.symbols.create("toHashFormat"), args[0]->attrs(), "while locating the attribute 'toHashFormat'");
+    auto iteratorToHashFormat = state.getAttr(state.symbols.create("toHashFormat"), args[0]->attrs(), "while locating the attribute 'toHashFormat'");
     HashFormat hf = parseHashFormat(state.forceStringNoCtx(*iteratorToHashFormat->value, pos, "while evaluating the attribute 'toHashFormat'"));
 
     v.mkString(Hash::parseAny(hash, ha).to_string(hf, hf == HashFormat::SRI));