Generate tracy trace from chrome profile

contrib/fold-trace.rs

@@ -0,0 +1,88 @@
+use std::io;
+use std::io::BufRead;
+
+#[derive (PartialEq, Debug)]
+enum Direction {
+    In,
+    Out
+}
+
+#[derive (PartialEq, Debug)]
+struct Event {
+    ts: u128,
+    line: u64,
+    id: u64,
+    probe_name: String,
+    probe_direction: Direction,
+    line_col: String,
+    filename: String
+}
+
+fn main ()  {
+    let mut buf = String::new();
+    let mut stdin_h = io::stdin().lock();
+    let mut done = false;
+    let mut stack: Vec<Event> = Vec::new();
+    let mut line_nb: u64 = 1;
+    while !done {
+        match stdin_h.read_line(&mut buf) {
+            Ok(0) => done = true,
+            Ok(_) => process_line(&buf, &mut stack, &line_nb),
+            Err(_err) => {
+                panic!("Error while reading from stdin.");
+            }
+        }
+        line_nb += 1;
+        buf.clear();
+    }
+    eprintln!("NB lines: {}", line_nb);
+}
+
+fn print_stack_names (stack: &Vec<Event>) -> String {
+    let mut names_str = String::new();
+    for event in stack {
+        names_str.push_str(format!(";{}:{}:{}", &event.probe_name, &event.filename, &event.line_col).as_str());
+    };
+    names_str
+}
+
+fn process_line(line: &str, stack: &mut Vec<Event>, line_nb: &u64) {
+    let elems: Vec<&str> = line.split(' ').collect();
+    let probe_direction = match elems[1] {
+        "in" => Direction::In,
+        "out" => Direction::Out,
+        x => panic!("Unknown probe direction {}", x)
+    };
+
+    let probe_name = elems[4].to_string();
+    let filename = String::from(elems[3]);
+    let event = Event {
+        ts: elems[0].parse().expect(format!("Cannot parse timestamp for line {}", line_nb).as_str()),
+        id: elems[2].parse().expect(format!("Cannot parse probe id for line {}", line_nb).as_str()),
+        line: line_nb.clone(),
+        probe_name,
+        probe_direction,
+        line_col: String::from(elems[5]),
+        filename
+    };
+
+    if event.probe_direction == Direction::In {
+        stack.push(event);
+    } else {
+	println!("{}",event.id);
+        let in_event = stack.pop().expect("Error: cannot pop stack, we lack a in event.");
+        if !same_frame(&event, &in_event) {
+            eprintln!("Weird trace!! We found a unmatched out event for");
+            eprintln!("{:?}", in_event);
+            eprintln!("{:?}", event);
+            stack.push(in_event);
+            panic!();
+        }
+        let dur = event.ts - in_event.ts;
+        println!("{} {}", print_stack_names(&stack), dur);
+    }
+}
+
+fn same_frame(a: &Event, b: &Event) -> bool {
+    a.id == b.id
+}

profile.sh

@@ -0,0 +1,23 @@
+#!/usr/bin/env bash
+
+set -euo pipefail
+
+nix-shell --run "make -j '$(nproc --all)'"
+
+workspace=$(mktemp -d)
+
+function cleanup {
+    rm -rf "${workspace}"
+}
+
+trap cleanup EXIT
+
+chromejson="${workspace}"/out.json
+tracyfile="${workspace}"/out.tracy
+
+echo "[+] Instantiating derivation"
+NIX_SHOW_TRACE=1 ./outputs/out/bin/nix-instantiate $@ > "${chromejson}"
+
+echo "[+] Converting chrome profile to tracy profile"
+nix-shell -p tracy --run "import-chrome '${chromejson}' '${tracyfile}'"
+nix-shell -p tracy --run "tracy '${tracyfile}'"

src/libexpr/eval.cc

@@ -9,6 +9,7 @@
 #include "filetransfer.hh"
 #include "json.hh"
 #include "function-trace.hh"
+#include "tracing.hh"
 
 #include <algorithm>
 #include <chrono>
@@ -19,6 +20,7 @@
 #include <iostream>
 #include <fstream>
 #include <functional>
+#include <deque>
 
 #include <sys/resource.h>
 
@@ -37,6 +39,8 @@
 
 namespace nix {
 
+
+
 static char * allocString(size_t size)
 {
     char * t;
@@ -175,6 +179,8 @@ void Value::print(const SymbolTable & symbols, std::ostream & str,
     case tFloat:
         str << fpoint;
         break;
+    case tBlackhole:
+        str << "<BLACKHOLE - currently evaluating this attribute>";
     default:
         abort();
     }
@@ -479,6 +485,10 @@ EvalState::EvalState(
     , baseEnv(allocEnv(128))
     , staticBaseEnv{std::make_shared<StaticEnv>(false, nullptr)}
 {
+    bool showTrace = getEnv("NIX_SHOW_TRACE").value_or("0") != "0";
+    if (showTrace) {
+        tracingBuffer = std::make_unique<TracingBufferT>();
+    }
     countCalls = getEnv("NIX_COUNT_CALLS").value_or("0") != "0";
 
     assert(gcInitialised);
@@ -1265,17 +1275,85 @@ void EvalState::cacheFile(
     fileEvalCache[resolvedPath] = v;
     if (path != resolvedPath) fileEvalCache[path] = v;
 }
-
-
 void EvalState::eval(Expr * e, Value & v)
 {
+    NIX_TRACE_ES(*this, e)
     e->eval(*this, baseEnv, v);
 }
 
+void EvalState::printTraces() const {
+    bool showTrace = getEnv("NIX_SHOW_TRACE").value_or("0") != "0";
+
+    if (!tracingBuffer || !showTrace) {
+        return;
+    }
+
+    std::deque<TracingBufferT::TC::Entry*> stack;
+    std::cout << "[" << std::endl;
+    auto writeComma = false;
+    for (auto it = tracingBuffer->chunks.begin(); it != tracingBuffer->chunks.end(); it++) {
+        auto & chunk = *it;
+        for (size_t i = 0; i < chunk.pos; i++) {
+            auto * e = &chunk.data[i];
+            if(writeComma) {
+                std::cout << ",";
+            } else {
+                writeComma = true;
+            }
+            std::cout << "{\"name\": \"" << e->data.file << " " << e->data.line
+                      << " " << e->data.type << "\", \"cat\": \""
+                      << "empty"
+                      << "\", \"ph\": \"X\", \"pid\": 0, \"tid\": 0, \"ts\": "
+                      << e->ts_entry
+                      << ", \"dur\":" << e->ts_exit - e->ts_entry
+                      << "}"
+                      << std::endl;
+
+            //size_t n = 0;
+            //for (auto eit = stack.rbegin(); eit != stack.rend(); eit++) {
+            //    auto element = *eit;
+            //    if (element->ts_exit < e->ts_entry) {
+            //        n++;
+            //        std::cout << element->ts_exit << " out ";
+            //        element->data.print(std::cout);
+            //        std::cout << " " << std::endl;
+            //        assert(!element->data.invalid);
+            //        element->data.invalid = true;
+            //    } else {
+            //        break;
+            //    }
+            //}
+
+            //while (n > 0) {
+            //    stack.pop_back();
+            //    n--;
+            //}
+
+            //std::cout << e->ts_entry << " in ";
+            //e->data.print(std::cout);
+            //std::cout << " " << std::endl;
+
+            //stack.push_back(e);
+        }
+    }
+
+    std::cout << "]";
+
+    for (auto eit = stack.rbegin(); eit != stack.rend(); eit++) {
+        auto element = *eit;
+        std::cout << element->ts_exit << " out ";
+        element->data.print(std::cout);
+        std::cout << " " << std::endl;
+        assert(!element->data.invalid);
+        element->data.invalid = true;
+    }
+}
+
 
 inline bool EvalState::evalBool(Env & env, Expr * e)
 {
     Value v;
+    NIX_TRACE_TOP(*this,e)
     e->eval(*this, env, v);
     if (v.type() != nBool)
         throwTypeError(noPos, "value is %1% while a Boolean was expected", v, env, *e);
@@ -1286,6 +1364,7 @@ inline bool EvalState::evalBool(Env & env, Expr * e)
 inline bool EvalState::evalBool(Env & env, Expr * e, const PosIdx pos)
 {
     Value v;
+    NIX_TRACE_TOP(*this, e)
     e->eval(*this, env, v);
     if (v.type() != nBool)
         throwTypeError(pos, "value is %1% while a Boolean was expected", v, env, *e);
@@ -1295,6 +1374,7 @@ inline bool EvalState::evalBool(Env & env, Expr * e, const PosIdx pos)
 
 inline void EvalState::evalAttrs(Env & env, Expr * e, Value & v)
 {
+    NIX_TRACE_TOP(*this, e)
     e->eval(*this, env, v);
     if (v.type() != nAttrs)
         throwTypeError(noPos, "value is %1% while a set was expected", v, env, *e);
@@ -1309,29 +1389,34 @@ void Expr::eval(EvalState & state, Env & env, Value & v)
 
 void ExprInt::eval(EvalState & state, Env & env, Value & v)
 {
-    v = this->v;
+  NIX_TRACE_ES(state, this)
+  v = this->v;
 }
 
 
 void ExprFloat::eval(EvalState & state, Env & env, Value & v)
 {
-    v = this->v;
+  NIX_TRACE_ES(state, this)
+  v = this->v;
 }
 
 void ExprString::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v = this->v;
 }
 
 
 void ExprPath::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v = this->v;
 }
 
 
 void ExprAttrs::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkAttrs(state.buildBindings(attrs.size() + dynamicAttrs.size()).finish());
     auto dynamicEnv = &env;
 
@@ -1416,6 +1501,7 @@ void ExprAttrs::eval(EvalState & state, Env & env, Value & v)
 
 void ExprLet::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     /* Create a new environment that contains the attributes in this
        `let'. */
     Env & env2(state.allocEnv(attrs->attrs.size()));
@@ -1434,6 +1520,7 @@ void ExprLet::eval(EvalState & state, Env & env, Value & v)
 
 void ExprList::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     state.mkList(v, elems.size());
     for (auto [n, v2] : enumerate(v.listItems()))
         const_cast<Value * &>(v2) = elems[n]->maybeThunk(state, env);
@@ -1442,6 +1529,7 @@ void ExprList::eval(EvalState & state, Env & env, Value & v)
 
 void ExprVar::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     Value * v2 = state.lookupVar(&env, *this, false);
     state.forceValue(*v2, pos);
     v = *v2;
@@ -1469,6 +1557,8 @@ static std::string showAttrPath(EvalState & state, Env & env, const AttrPath & a
 
 void ExprSelect::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
+
     Value vTmp;
     PosIdx pos2;
     Value * vAttrs = &vTmp;
@@ -1534,6 +1624,7 @@ void ExprOpHasAttr::eval(EvalState & state, Env & env, Value & v)
     Value vTmp;
     Value * vAttrs = &vTmp;
 
+    NIX_TRACE_ES(state, this)
     e->eval(state, env, vTmp);
 
     for (auto & i : attrPath) {
@@ -1556,6 +1647,7 @@ void ExprOpHasAttr::eval(EvalState & state, Env & env, Value & v)
 
 void ExprLambda::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkLambda(&env, this);
 }
 
@@ -1749,6 +1841,7 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
 void ExprCall::eval(EvalState & state, Env & env, Value & v)
 {
     Value vFun;
+    NIX_TRACE_ES(state, this)
     fun->eval(state, env, vFun);
 
     Value * vArgs[args.size()];
@@ -1808,7 +1901,7 @@ void EvalState::autoCallFunction(Bindings & args, Value & fun, Value & res)
 Nix attempted to evaluate a function as a top level expression; in
 this case it must have its arguments supplied either by default
 values, or passed explicitly with '--arg' or '--argstr'. See
-https://nixos.org/manual/nix/stable/expressions/language-constructs.html#functions.)", symbols[i.name],                 
+https://nixos.org/manual/nix/stable/expressions/language-constructs.html#functions.)", symbols[i.name],
                 *fun.lambda.env, *fun.lambda.fun);
             }
         }
@@ -1820,6 +1913,7 @@ https://nixos.org/manual/nix/stable/expressions/language-constructs.html#functio
 
 void ExprWith::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     Env & env2(state.allocEnv(1));
     env2.up = &env;
     env2.prevWith = prevWith;
@@ -1832,12 +1926,14 @@ void ExprWith::eval(EvalState & state, Env & env, Value & v)
 
 void ExprIf::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     (state.evalBool(env, cond, pos) ? then : else_)->eval(state, env, v);
 }
 
 
 void ExprAssert::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     if (!state.evalBool(env, cond, pos)) {
         std::ostringstream out;
         cond->show(state.symbols, out);
@@ -1849,12 +1945,14 @@ void ExprAssert::eval(EvalState & state, Env & env, Value & v)
 
 void ExprOpNot::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkBool(!state.evalBool(env, e));
 }
 
 
 void ExprOpEq::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     Value v1; e1->eval(state, env, v1);
     Value v2; e2->eval(state, env, v2);
     v.mkBool(state.eqValues(v1, v2));
@@ -1863,6 +1961,7 @@ void ExprOpEq::eval(EvalState & state, Env & env, Value & v)
 
 void ExprOpNEq::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     Value v1; e1->eval(state, env, v1);
     Value v2; e2->eval(state, env, v2);
     v.mkBool(!state.eqValues(v1, v2));
@@ -1871,18 +1970,21 @@ void ExprOpNEq::eval(EvalState & state, Env & env, Value & v)
 
 void ExprOpAnd::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkBool(state.evalBool(env, e1, pos) && state.evalBool(env, e2, pos));
 }
 
 
 void ExprOpOr::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkBool(state.evalBool(env, e1, pos) || state.evalBool(env, e2, pos));
 }
 
 
 void ExprOpImpl::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     v.mkBool(!state.evalBool(env, e1, pos) || state.evalBool(env, e2, pos));
 }
 
@@ -1890,6 +1992,7 @@ void ExprOpImpl::eval(EvalState & state, Env & env, Value & v)
 void ExprOpUpdate::eval(EvalState & state, Env & env, Value & v)
 {
     Value v1, v2;
+    NIX_TRACE_ES(state, this)
     state.evalAttrs(env, e1, v1);
     state.evalAttrs(env, e2, v2);
 
@@ -1927,6 +2030,7 @@ void ExprOpUpdate::eval(EvalState & state, Env & env, Value & v)
 
 void ExprOpConcatLists::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     Value v1; e1->eval(state, env, v1);
     Value v2; e2->eval(state, env, v2);
     Value * lists[2] = { &v1, &v2 };
@@ -1965,6 +2069,7 @@ void EvalState::concatLists(Value & v, size_t nrLists, Value * * lists, const Po
 
 void ExprConcatStrings::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     PathSet context;
     std::vector<BackedStringView> s;
     size_t sSize = 0;
@@ -2054,6 +2159,7 @@ void ExprConcatStrings::eval(EvalState & state, Env & env, Value & v)
 
 void ExprPos::eval(EvalState & state, Env & env, Value & v)
 {
+    NIX_TRACE_ES(state, this)
     state.mkPos(v, pos);
 }
 

src/libexpr/eval.hh

@@ -7,6 +7,7 @@
 #include "symbol-table.hh"
 #include "config.hh"
 #include "experimental-features.hh"
+#include "tracing.hh"
 
 #include <map>
 #include <optional>
@@ -92,6 +93,7 @@ class EvalState : public std::enable_shared_from_this<EvalState>
 public:
     SymbolTable symbols;
     PosTable positions;
+    std::unique_ptr<TracingBufferT> tracingBuffer;
 
     static inline std::string derivationNixPath = "//builtin/derivation.nix";
 
@@ -126,6 +128,8 @@ public:
     RootValue vCallFlake = nullptr;
     RootValue vImportedDrvToDerivation = nullptr;
 
+    void printTraces() const;
+
     /* Debugger */
     void (* debugRepl)(ref<EvalState> es, const ValMap & extraEnv);
     bool debugStop;

src/libexpr/nixexpr.hh

@@ -147,6 +147,7 @@ struct Expr
     virtual Value * maybeThunk(EvalState & state, Env & env);
     virtual void setName(Symbol name);
     virtual PosIdx getPos() const { return noPos; }
+    virtual const char* showExprType() const { return "undefined"; }
 };
 
 #define COMMON_METHODS \
@@ -160,6 +161,7 @@ struct ExprInt : Expr
     Value v;
     ExprInt(NixInt n) : n(n) { v.mkInt(n); };
     Value * maybeThunk(EvalState & state, Env & env) override;
+    const char* showExprType() const { return "int"; }
     COMMON_METHODS
 };
 
@@ -169,6 +171,7 @@ struct ExprFloat : Expr
     Value v;
     ExprFloat(NixFloat nf) : nf(nf) { v.mkFloat(nf); };
     Value * maybeThunk(EvalState & state, Env & env) override;
+    const char* showExprType() const { return "float"; }
     COMMON_METHODS
 };
 
@@ -178,6 +181,7 @@ struct ExprString : Expr
     Value v;
     ExprString(std::string s) : s(std::move(s)) { v.mkString(this->s.data()); };
     Value * maybeThunk(EvalState & state, Env & env) override;
+    const char* showExprType() const { return "string"; }
     COMMON_METHODS
 };
 
@@ -187,6 +191,7 @@ struct ExprPath : Expr
     Value v;
     ExprPath(std::string s) : s(std::move(s)) { v.mkPath(this->s.c_str()); };
     Value * maybeThunk(EvalState & state, Env & env) override;
+    const char* showExprType() const { return "path"; }
     COMMON_METHODS
 };
 
@@ -215,6 +220,7 @@ struct ExprVar : Expr
     ExprVar(const PosIdx & pos, Symbol name) : pos(pos), name(name) { };
     Value * maybeThunk(EvalState & state, Env & env) override;
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "var"; }
     COMMON_METHODS
 };
 
@@ -226,6 +232,7 @@ struct ExprSelect : Expr
     ExprSelect(const PosIdx & pos, Expr * e, const AttrPath & attrPath, Expr * def) : pos(pos), e(e), def(def), attrPath(attrPath) { };
     ExprSelect(const PosIdx & pos, Expr * e, Symbol name) : pos(pos), e(e), def(0) { attrPath.push_back(AttrName(name)); };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "select"; }
     COMMON_METHODS
 };
 
@@ -235,6 +242,7 @@ struct ExprOpHasAttr : Expr
     AttrPath attrPath;
     ExprOpHasAttr(Expr * e, const AttrPath & attrPath) : e(e), attrPath(attrPath) { };
     PosIdx getPos() const override { return e->getPos(); }
+    const char* showExprType() const { return "op_has_attr"; }
     COMMON_METHODS
 };
 
@@ -264,6 +272,7 @@ struct ExprAttrs : Expr
     ExprAttrs(const PosIdx &pos) : recursive(false), pos(pos) { };
     ExprAttrs() : recursive(false) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "attrs"; }
     COMMON_METHODS
 };
 
@@ -271,6 +280,7 @@ struct ExprList : Expr
 {
     std::vector<Expr *> elems;
     ExprList() { };
+    const char* showExprType() const { return "list"; }
     COMMON_METHODS
 
     PosIdx getPos() const override
@@ -330,6 +340,7 @@ struct ExprLambda : Expr
     std::string showNamePos(const EvalState & state) const;
     inline bool hasFormals() const { return formals != nullptr; }
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "lambda"; }
     COMMON_METHODS
 };
 
@@ -342,6 +353,7 @@ struct ExprCall : Expr
         : fun(fun), args(args), pos(pos)
     { }
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "call"; }
     COMMON_METHODS
 };
 
@@ -350,6 +362,7 @@ struct ExprLet : Expr
     ExprAttrs * attrs;
     Expr * body;
     ExprLet(ExprAttrs * attrs, Expr * body) : attrs(attrs), body(body) { };
+    const char* showExprType() const { return "let"; }
     COMMON_METHODS
 };
 
@@ -360,6 +373,7 @@ struct ExprWith : Expr
     size_t prevWith;
     ExprWith(const PosIdx & pos, Expr * attrs, Expr * body) : pos(pos), attrs(attrs), body(body) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "with"; }
     COMMON_METHODS
 };
 
@@ -369,6 +383,7 @@ struct ExprIf : Expr
     Expr * cond, * then, * else_;
     ExprIf(const PosIdx & pos, Expr * cond, Expr * then, Expr * else_) : pos(pos), cond(cond), then(then), else_(else_) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "if"; }
     COMMON_METHODS
 };
 
@@ -378,6 +393,7 @@ struct ExprAssert : Expr
     Expr * cond, * body;
     ExprAssert(const PosIdx & pos, Expr * cond, Expr * body) : pos(pos), cond(cond), body(body) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "assert"; }
     COMMON_METHODS
 };
 
@@ -385,6 +401,7 @@ struct ExprOpNot : Expr
 {
     Expr * e;
     ExprOpNot(Expr * e) : e(e) { };
+    const char* showExprType() const { return "op_not"; }
     COMMON_METHODS
 };
 
@@ -405,6 +422,7 @@ struct ExprOpNot : Expr
         } \
         void eval(EvalState & state, Env & env, Value & v) override; \
         PosIdx getPos() const override { return pos; } \
+        const char* showExprType() const { return #name; } \
     };
 
 MakeBinOp(ExprOpEq, "==")
@@ -423,6 +441,7 @@ struct ExprConcatStrings : Expr
     ExprConcatStrings(const PosIdx & pos, bool forceString, std::vector<std::pair<PosIdx, Expr *>> * es)
         : pos(pos), forceString(forceString), es(es) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "concat_strings"; }
     COMMON_METHODS
 };
 
@@ -431,6 +450,7 @@ struct ExprPos : Expr
     PosIdx pos;
     ExprPos(const PosIdx & pos) : pos(pos) { };
     PosIdx getPos() const override { return pos; }
+    const char* showExprType() const { return "pos"; }
     COMMON_METHODS
 };
 

src/libexpr/primops.cc

@@ -11,6 +11,7 @@
 #include "value-to-json.hh"
 #include "value-to-xml.hh"
 #include "primops.hh"
+#include "tracing.hh"
 
 #include <boost/container/small_vector.hpp>
 
@@ -101,6 +102,8 @@ static Path realisePath(EvalState & state, const PosIdx pos, Value & v, const Re
 {
     PathSet context;
 
+    NIX_TRACE(state, state.positions[pos], "realisePath");
+
     auto path = [&]()
     {
         try {
@@ -160,6 +163,7 @@ static void mkOutputString(
    argument. */
 static void import(EvalState & state, const PosIdx pos, Value & vPath, Value * vScope, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "import");
     auto path = realisePath(state, pos, vPath);
 
     // FIXME
@@ -313,6 +317,7 @@ extern "C" typedef void (*ValueInitializer)(EvalState & state, Value & v);
 /* Load a ValueInitializer from a DSO and return whatever it initializes */
 void prim_importNative(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "importNative");
     auto path = realisePath(state, pos, *args[0]);
 
     std::string sym(state.forceStringNoCtx(*args[1], pos));
@@ -340,6 +345,7 @@ void prim_importNative(EvalState & state, const PosIdx pos, Value * * args, Valu
 /* Execute a program and parse its output */
 void prim_exec(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "exec");
     state.forceList(*args[0], pos);
     auto elems = args[0]->listElems();
     auto count = args[0]->listSize();
@@ -385,6 +391,7 @@ void prim_exec(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 /* Return a string representing the type of the expression. */
 static void prim_typeOf(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "typeOf");
     state.forceValue(*args[0], pos);
     std::string t;
     switch (args[0]->type()) {
@@ -419,6 +426,7 @@ static RegisterPrimOp primop_typeOf({
 /* Determine whether the argument is the null value. */
 static void prim_isNull(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isNull");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nNull);
 }
@@ -439,6 +447,7 @@ static RegisterPrimOp primop_isNull({
 /* Determine whether the argument is a function. */
 static void prim_isFunction(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isFunction");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nFunction);
 }
@@ -455,6 +464,7 @@ static RegisterPrimOp primop_isFunction({
 /* Determine whether the argument is an integer. */
 static void prim_isInt(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isInt");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nInt);
 }
@@ -471,6 +481,7 @@ static RegisterPrimOp primop_isInt({
 /* Determine whether the argument is a float. */
 static void prim_isFloat(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isFloat");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nFloat);
 }
@@ -487,6 +498,7 @@ static RegisterPrimOp primop_isFloat({
 /* Determine whether the argument is a string. */
 static void prim_isString(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isString");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nString);
 }
@@ -503,6 +515,7 @@ static RegisterPrimOp primop_isString({
 /* Determine whether the argument is a Boolean. */
 static void prim_isBool(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isBool");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nBool);
 }
@@ -519,6 +532,7 @@ static RegisterPrimOp primop_isBool({
 /* Determine whether the argument is a path. */
 static void prim_isPath(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isPath");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nPath);
 }
@@ -619,6 +633,7 @@ static Bindings::iterator getAttr(
 
 static void prim_genericClosure(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "genericClosure");
     state.forceAttrs(*args[0], pos);
 
     /* Get the start set. */
@@ -733,6 +748,7 @@ static RegisterPrimOp primop_break({
     )",
     .fun = [](EvalState & state, const PosIdx pos, Value * * args, Value & v)
     {
+        NIX_TRACE(state, state.positions[pos], "break");
         if (state.debugRepl && !state.debugTraces.empty()) {
             auto error = Error(ErrorInfo {
                 .level = lvlInfo,
@@ -766,6 +782,7 @@ static RegisterPrimOp primop_abort({
     )",
     .fun = [](EvalState & state, const PosIdx pos, Value * * args, Value & v)
     {
+        NIX_TRACE(state, state.positions[pos], "abort");
         PathSet context;
         auto s = state.coerceToString(pos, *args[0], context).toOwned();
         state.debugThrowLastTrace(Abort("evaluation aborted with the following error message: '%1%'", s));
@@ -784,6 +801,7 @@ static RegisterPrimOp primop_throw({
     )",
     .fun = [](EvalState & state, const PosIdx pos, Value * * args, Value & v)
     {
+      NIX_TRACE(state, state.positions[pos], "throw");
       PathSet context;
       auto s = state.coerceToString(pos, *args[0], context).toOwned();
       state.debugThrowLastTrace(ThrownError(s));
@@ -792,6 +810,7 @@ static RegisterPrimOp primop_throw({
 
 static void prim_addErrorContext(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "addErrorContext");
     try {
         state.forceValue(*args[1], pos);
         v = *args[1];
@@ -810,6 +829,7 @@ static RegisterPrimOp primop_addErrorContext(RegisterPrimOp::Info {
 
 static void prim_ceil(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "ceil");
     auto value = state.forceFloat(*args[0], args[0]->determinePos(pos));
     v.mkInt(ceil(value));
 }
@@ -829,6 +849,8 @@ static RegisterPrimOp primop_ceil({
 
 static void prim_floor(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "floor");
+
     auto value = state.forceFloat(*args[0], args[0]->determinePos(pos));
     v.mkInt(floor(value));
 }
@@ -850,6 +872,7 @@ static RegisterPrimOp primop_floor({
  * else => {success=false; value=false;} */
 static void prim_tryEval(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "tryEval");
     auto attrs = state.buildBindings(2);
 
     /* increment state.trylevel, and decrement it when this function returns. */
@@ -903,6 +926,7 @@ static RegisterPrimOp primop_tryEval({
 /* Return an environment variable.  Use with care. */
 static void prim_getEnv(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "getEnv");
     std::string name(state.forceStringNoCtx(*args[0], pos));
     v.mkString(evalSettings.restrictEval || evalSettings.pureEval ? "" : getEnv(name).value_or(""));
 }
@@ -927,6 +951,7 @@ static RegisterPrimOp primop_getEnv({
 /* Evaluate the first argument, then return the second argument. */
 static void prim_seq(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "seq");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
     v = *args[1];
@@ -946,6 +971,7 @@ static RegisterPrimOp primop_seq({
    attrsets), then return the second argument. */
 static void prim_deepSeq(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "deepSeq");
     state.forceValueDeep(*args[0]);
     state.forceValue(*args[1], pos);
     v = *args[1];
@@ -966,6 +992,7 @@ static RegisterPrimOp primop_deepSeq({
    return the second expression.  Useful for debugging. */
 static void prim_trace(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "trace");
     state.forceValue(*args[0], pos);
     if (args[0]->type() == nString)
         printError("trace: %1%", args[0]->string.s);
@@ -992,6 +1019,7 @@ static RegisterPrimOp primop_trace({
  */
 static void prim_second(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "second");
     state.forceValue(*args[1], pos);
     v = *args[1];
 }
@@ -1010,6 +1038,7 @@ static void prim_second(EvalState & state, const PosIdx pos, Value * * args, Val
    derivation. */
 static void prim_derivationStrict(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "derivationStrict");
     state.forceAttrs(*args[0], pos);
 
     /* Figure out the name first (for stack backtraces). */
@@ -1368,6 +1397,7 @@ static RegisterPrimOp primop_derivationStrict(RegisterPrimOp::Info {
    ‘out’. */
 static void prim_placeholder(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "placeholder");
     v.mkString(hashPlaceholder(state.forceStringNoCtx(*args[0], pos)));
 }
 
@@ -1391,6 +1421,7 @@ static RegisterPrimOp primop_placeholder({
 /* Convert the argument to a path.  !!! obsolete? */
 static void prim_toPath(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "toPath");
     PathSet context;
     Path path = state.coerceToPath(pos, *args[0], context);
     v.mkString(canonPath(path), context);
@@ -1416,6 +1447,7 @@ static RegisterPrimOp primop_toPath({
    corner cases. */
 static void prim_storePath(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "storePath");
     if (evalSettings.pureEval)
         state.debugThrowLastTrace(EvalError({
             .msg = hintfmt("'%s' is not allowed in pure evaluation mode", "builtins.storePath"),
@@ -1460,6 +1492,7 @@ static RegisterPrimOp primop_storePath({
 
 static void prim_pathExists(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "pathExists");
     /* We don’t check the path right now, because we don’t want to
       throw if the path isn’t allowed, but just return false (and we
       can’t just catch the exception here because we still want to
@@ -1492,6 +1525,7 @@ static RegisterPrimOp primop_pathExists({
    following the last slash. */
 static void prim_baseNameOf(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "baseNameOf");
     PathSet context;
     v.mkString(baseNameOf(*state.coerceToString(pos, *args[0], context, false, false)), context);
 }
@@ -1512,6 +1546,7 @@ static RegisterPrimOp primop_baseNameOf({
    of the argument. */
 static void prim_dirOf(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "dirOf");
     PathSet context;
     auto path = state.coerceToString(pos, *args[0], context, false, false);
     auto dir = dirOf(*path);
@@ -1532,6 +1567,7 @@ static RegisterPrimOp primop_dirOf({
 /* Return the contents of a file as a string. */
 static void prim_readFile(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "readFile");
     auto path = realisePath(state, pos, *args[0]);
     auto s = readFile(path);
     if (s.find((char) 0) != std::string::npos)
@@ -1560,6 +1596,7 @@ static RegisterPrimOp primop_readFile({
    which are desugared to 'findFile __nixPath "x"'. */
 static void prim_findFile(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "findFile");
     state.forceList(*args[0], pos);
 
     SearchPath searchPath;
@@ -1610,6 +1647,7 @@ static RegisterPrimOp primop_findFile(RegisterPrimOp::Info {
 /* Return the cryptographic hash of a file in base-16. */
 static void prim_hashFile(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "hashFile");
     auto type = state.forceStringNoCtx(*args[0], pos);
     std::optional<HashType> ht = parseHashType(type);
     if (!ht)
@@ -1637,6 +1675,7 @@ static RegisterPrimOp primop_hashFile({
 /* Read a directory (without . or ..) */
 static void prim_readDir(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "readDir");
     auto path = realisePath(state, pos, *args[0]);
 
     DirEntries entries = readDirectory(path);
@@ -1686,6 +1725,7 @@ static RegisterPrimOp primop_readDir({
    be sensibly or completely represented (e.g., functions). */
 static void prim_toXML(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "toXML");
     std::ostringstream out;
     PathSet context;
     printValueAsXML(state, true, false, *args[0], out, context, pos);
@@ -1794,6 +1834,7 @@ static RegisterPrimOp primop_toXML({
    represented (e.g., functions). */
 static void prim_toJSON(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "toJSON");
     std::ostringstream out;
     PathSet context;
     printValueAsJSON(state, true, *args[0], pos, out, context);
@@ -1817,6 +1858,7 @@ static RegisterPrimOp primop_toJSON({
 /* Parse a JSON string to a value. */
 static void prim_fromJSON(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "fromJSON");
     auto s = state.forceStringNoCtx(*args[0], pos);
     try {
         parseJSON(state, s, v);
@@ -1845,6 +1887,7 @@ static RegisterPrimOp primop_fromJSON({
    as an input by derivations. */
 static void prim_toFile(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "toFile");
     PathSet context;
     std::string name(state.forceStringNoCtx(*args[0], pos));
     std::string contents(state.forceString(*args[1], context, pos));
@@ -1964,6 +2007,7 @@ static void addPath(
     Value & v,
     const PathSet & context)
 {
+    NIX_TRACE(state, state.positions[pos], "addPath");
     try {
         // FIXME: handle CA derivation outputs (where path needs to
         // be rewritten to the actual output).
@@ -2030,6 +2074,7 @@ static void addPath(
 
 static void prim_filterSource(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "filterSource");
     PathSet context;
     Path path = state.coerceToPath(pos, *args[1], context);
 
@@ -2102,6 +2147,7 @@ static RegisterPrimOp primop_filterSource({
 
 static void prim_path(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "path");
     state.forceAttrs(*args[0], pos);
     Path path;
     std::string name;
@@ -2185,6 +2231,7 @@ static RegisterPrimOp primop_path({
    strings. */
 static void prim_attrNames(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "attrNames");
     state.forceAttrs(*args[0], pos);
 
     state.mkList(v, args[0]->attrs->size());
@@ -2212,6 +2259,7 @@ static RegisterPrimOp primop_attrNames({
    order as attrNames. */
 static void prim_attrValues(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "attrValues");
     state.forceAttrs(*args[0], pos);
 
     state.mkList(v, args[0]->attrs->size());
@@ -2244,6 +2292,7 @@ static RegisterPrimOp primop_attrValues({
 /* Dynamic version of the `.' operator. */
 void prim_getAttr(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "getAttr");
     auto attr = state.forceStringNoCtx(*args[0], pos);
     state.forceAttrs(*args[1], pos);
     Bindings::iterator i = getAttr(
@@ -2274,6 +2323,7 @@ static RegisterPrimOp primop_getAttr({
 /* Return position information of the specified attribute. */
 static void prim_unsafeGetAttrPos(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "unsafeGetAttrPos");
     auto attr = state.forceStringNoCtx(*args[0], pos);
     state.forceAttrs(*args[1], pos);
     Bindings::iterator i = args[1]->attrs->find(state.symbols.create(attr));
@@ -2292,6 +2342,7 @@ static RegisterPrimOp primop_unsafeGetAttrPos(RegisterPrimOp::Info {
 /* Dynamic version of the `?' operator. */
 static void prim_hasAttr(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "hasAttr");
     auto attr = state.forceStringNoCtx(*args[0], pos);
     state.forceAttrs(*args[1], pos);
     v.mkBool(args[1]->attrs->find(state.symbols.create(attr)) != args[1]->attrs->end());
@@ -2311,6 +2362,7 @@ static RegisterPrimOp primop_hasAttr({
 /* Determine whether the argument is a set. */
 static void prim_isAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isAttrs");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nAttrs);
 }
@@ -2326,6 +2378,7 @@ static RegisterPrimOp primop_isAttrs({
 
 static void prim_removeAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "removeAttrs");
     state.forceAttrs(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -2374,6 +2427,7 @@ static RegisterPrimOp primop_removeAttrs({
    name, the first takes precedence. */
 static void prim_listToAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "listToAttrs");
     state.forceList(*args[0], pos);
 
     auto attrs = state.buildBindings(args[0]->listSize());
@@ -2436,6 +2490,7 @@ static RegisterPrimOp primop_listToAttrs({
 
 static void prim_intersectAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "intersectAttrs");
     state.forceAttrs(*args[0], pos);
     state.forceAttrs(*args[1], pos);
 
@@ -2462,6 +2517,7 @@ static RegisterPrimOp primop_intersectAttrs({
 
 static void prim_catAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "catAttrs");
     auto attrName = state.symbols.create(state.forceStringNoCtx(*args[0], pos));
     state.forceList(*args[1], pos);
 
@@ -2499,6 +2555,7 @@ static RegisterPrimOp primop_catAttrs({
 
 static void prim_functionArgs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "functionArgs");
     state.forceValue(*args[0], pos);
     if (args[0]->isPrimOpApp() || args[0]->isPrimOp()) {
         v.mkAttrs(&state.emptyBindings);
@@ -2542,6 +2599,7 @@ static RegisterPrimOp primop_functionArgs({
 /*  */
 static void prim_mapAttrs(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "mapAttrs");
     state.forceAttrs(*args[1], pos);
 
     auto attrs = state.buildBindings(args[1]->attrs->size());
@@ -2574,6 +2632,7 @@ static RegisterPrimOp primop_mapAttrs({
 
 static void prim_zipAttrsWith(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "zipAttrsWith");
     // we will first count how many values are present for each given key.
     // we then allocate a single attrset and pre-populate it with lists of
     // appropriate sizes, stash the pointers to the list elements of each,
@@ -2666,6 +2725,7 @@ static RegisterPrimOp primop_zipAttrsWith({
 /* Determine whether the argument is a list. */
 static void prim_isList(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "isList");
     state.forceValue(*args[0], pos);
     v.mkBool(args[0]->type() == nList);
 }
@@ -2681,6 +2741,7 @@ static RegisterPrimOp primop_isList({
 
 static void elemAt(EvalState & state, const PosIdx pos, Value & list, int n, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "elemAt");
     state.forceList(list, pos);
     if (n < 0 || (unsigned int) n >= list.listSize())
         state.debugThrowLastTrace(Error({
@@ -2694,6 +2755,7 @@ static void elemAt(EvalState & state, const PosIdx pos, Value & list, int n, Val
 /* Return the n-1'th element of a list. */
 static void prim_elemAt(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "elemAt");
     elemAt(state, pos, *args[0], state.forceInt(*args[1], pos), v);
 }
 
@@ -2710,6 +2772,7 @@ static RegisterPrimOp primop_elemAt({
 /* Return the first element of a list. */
 static void prim_head(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "head");
     elemAt(state, pos, *args[0], 0, v);
 }
 
@@ -2729,6 +2792,7 @@ static RegisterPrimOp primop_head({
    don't want to use it!  */
 static void prim_tail(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "tail");
     state.forceList(*args[0], pos);
     if (args[0]->listSize() == 0)
         state.debugThrowLastTrace(Error({
@@ -2760,6 +2824,7 @@ static RegisterPrimOp primop_tail({
 /* Apply a function to every element of a list. */
 static void prim_map(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "map");
     state.forceList(*args[1], pos);
 
     state.mkList(v, args[1]->listSize());
@@ -2790,6 +2855,7 @@ static RegisterPrimOp primop_map({
    returns true. */
 static void prim_filter(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "filter");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -2828,6 +2894,7 @@ static RegisterPrimOp primop_filter({
 /* Return true if a list contains a given element. */
 static void prim_elem(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "elem");
     bool res = false;
     state.forceList(*args[1], pos);
     for (auto elem : args[1]->listItems())
@@ -2851,6 +2918,7 @@ static RegisterPrimOp primop_elem({
 /* Concatenate a list of lists. */
 static void prim_concatLists(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "concatLists");
     state.forceList(*args[0], pos);
     state.concatLists(v, args[0]->listSize(), args[0]->listElems(), pos);
 }
@@ -2867,6 +2935,7 @@ static RegisterPrimOp primop_concatLists({
 /* Return the length of a list.  This is an O(1) time operation. */
 static void prim_length(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "length");
     state.forceList(*args[0], pos);
     v.mkInt(args[0]->listSize());
 }
@@ -2884,6 +2953,7 @@ static RegisterPrimOp primop_length({
    right. The operator is applied strictly. */
 static void prim_foldlStrict(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "foldlStrict");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[2], pos);
 
@@ -2917,6 +2987,7 @@ static RegisterPrimOp primop_foldlStrict({
 
 static void anyOrAll(bool any, EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "anyOrAll");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -2936,6 +3007,7 @@ static void anyOrAll(bool any, EvalState & state, const PosIdx pos, Value * * ar
 
 static void prim_any(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "any");
     anyOrAll(true, state, pos, args, v);
 }
 
@@ -2951,6 +3023,7 @@ static RegisterPrimOp primop_any({
 
 static void prim_all(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "all");
     anyOrAll(false, state, pos, args, v);
 }
 
@@ -2966,6 +3039,7 @@ static RegisterPrimOp primop_all({
 
 static void prim_genList(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "genList");
     auto len = state.forceInt(*args[1], pos);
 
     if (len < 0)
@@ -3004,6 +3078,7 @@ static void prim_lessThan(EvalState & state, const PosIdx pos, Value * * args, V
 
 static void prim_sort(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "sort");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -3055,6 +3130,7 @@ static RegisterPrimOp primop_sort({
 
 static void prim_partition(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "partition");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -3115,6 +3191,7 @@ static RegisterPrimOp primop_partition({
 
 static void prim_groupBy(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "groupBy");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
 
@@ -3167,6 +3244,7 @@ static RegisterPrimOp primop_groupBy({
 
 static void prim_concatMap(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "concatMap");
     state.forceFunction(*args[0], pos);
     state.forceList(*args[1], pos);
     auto nrLists = args[1]->listSize();
@@ -3214,6 +3292,7 @@ static RegisterPrimOp primop_concatMap({
 
 static void prim_add(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "add");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
     if (args[0]->type() == nFloat || args[1]->type() == nFloat)
@@ -3233,6 +3312,7 @@ static RegisterPrimOp primop_add({
 
 static void prim_sub(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "sub");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
     if (args[0]->type() == nFloat || args[1]->type() == nFloat)
@@ -3252,6 +3332,7 @@ static RegisterPrimOp primop_sub({
 
 static void prim_mul(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "mul");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
     if (args[0]->type() == nFloat || args[1]->type() == nFloat)
@@ -3271,6 +3352,7 @@ static RegisterPrimOp primop_mul({
 
 static void prim_div(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "div");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
 
@@ -3308,6 +3390,7 @@ static RegisterPrimOp primop_div({
 
 static void prim_bitAnd(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "bitAnd");
     v.mkInt(state.forceInt(*args[0], pos) & state.forceInt(*args[1], pos));
 }
 
@@ -3322,6 +3405,7 @@ static RegisterPrimOp primop_bitAnd({
 
 static void prim_bitOr(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "bitOr");
     v.mkInt(state.forceInt(*args[0], pos) | state.forceInt(*args[1], pos));
 }
 
@@ -3336,6 +3420,7 @@ static RegisterPrimOp primop_bitOr({
 
 static void prim_bitXor(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "bitXor");
     v.mkInt(state.forceInt(*args[0], pos) ^ state.forceInt(*args[1], pos));
 }
 
@@ -3350,6 +3435,7 @@ static RegisterPrimOp primop_bitXor({
 
 static void prim_lessThan(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "lessThan");
     state.forceValue(*args[0], pos);
     state.forceValue(*args[1], pos);
     CompareValues comp{state};
@@ -3378,6 +3464,7 @@ static RegisterPrimOp primop_lessThan({
    `"/nix/store/whatever..."'. */
 static void prim_toString(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "toString");
     PathSet context;
     auto s = state.coerceToString(pos, *args[0], context, true, false);
     v.mkString(*s, context);
@@ -3413,6 +3500,7 @@ static RegisterPrimOp primop_toString({
    non-negative. */
 static void prim_substring(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "substring");
     int start = state.forceInt(*args[0], pos);
     int len = state.forceInt(*args[1], pos);
     PathSet context;
@@ -3449,6 +3537,7 @@ static RegisterPrimOp primop_substring({
 
 static void prim_stringLength(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "stringLength");
     PathSet context;
     auto s = state.coerceToString(pos, *args[0], context);
     v.mkInt(s->size());
@@ -3467,6 +3556,7 @@ static RegisterPrimOp primop_stringLength({
 /* Return the cryptographic hash of a string in base-16. */
 static void prim_hashString(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "hashString");
     auto type = state.forceStringNoCtx(*args[0], pos);
     std::optional<HashType> ht = parseHashType(type);
     if (!ht)
@@ -3515,6 +3605,7 @@ std::shared_ptr<RegexCache> makeRegexCache()
 
 void prim_match(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "match");
     auto re = state.forceStringNoCtx(*args[0], pos);
 
     try {
@@ -3595,6 +3686,7 @@ static RegisterPrimOp primop_match({
    non-matching parts interleaved by the lists of the matching groups. */
 void prim_split(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "split");
     auto re = state.forceStringNoCtx(*args[0], pos);
 
     try {
@@ -3698,6 +3790,7 @@ static RegisterPrimOp primop_split({
 
 static void prim_concatStringsSep(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "concatStringsSep");
     PathSet context;
 
     auto sep = state.forceString(*args[0], context, pos);
@@ -3728,6 +3821,7 @@ static RegisterPrimOp primop_concatStringsSep({
 
 static void prim_replaceStrings(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "replaceStrings");
     state.forceList(*args[0], pos);
     state.forceList(*args[1], pos);
     if (args[0]->listSize() != args[1]->listSize())
@@ -3808,6 +3902,7 @@ static RegisterPrimOp primop_replaceStrings({
 
 static void prim_parseDrvName(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "parseDrvName");
     auto name = state.forceStringNoCtx(*args[0], pos);
     DrvName parsed(name);
     auto attrs = state.buildBindings(2);
@@ -3832,6 +3927,7 @@ static RegisterPrimOp primop_parseDrvName({
 
 static void prim_compareVersions(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "compareVersions");
     auto version1 = state.forceStringNoCtx(*args[0], pos);
     auto version2 = state.forceStringNoCtx(*args[1], pos);
     v.mkInt(compareVersions(version1, version2));
@@ -3852,6 +3948,7 @@ static RegisterPrimOp primop_compareVersions({
 
 static void prim_splitVersion(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
+    NIX_TRACE(state, state.positions[pos], "splitVersion");
     auto version = state.forceStringNoCtx(*args[0], pos);
     auto iter = version.cbegin();
     Strings components;

src/libexpr/tracing.cc

@@ -0,0 +1,20 @@
+#include "tracing.hh"
+
+static uint64_t trace_counter = 0;
+
+namespace nix {
+    TraceData::TraceData(Pos p, const char* t):
+        // If the origin is a String don't use the location as
+        // otherwise we emit the entire input string as "file".
+        file((p.origin == foString) ? "<string>" :
+             ((p.origin == foStdin) ? "<stdin>" : p.file)),
+        type(t),
+        line((p.origin == foString || p.origin == foStdin) ? 0 : p.line),
+        id(trace_counter++),
+        invalid(false)
+    {}
+
+    void TraceData::print(std::ostream & os) {
+        os << id << " " << (file.size() > 0 ? file : "<undefined>") << " " << (type ? type : "n/a") << " " << line << (invalid ? " invalid" : "");
+    }
+}

src/libexpr/tracing.hh

@@ -0,0 +1,129 @@
+#pragma once
+
+#include <ctime>
+#include <memory>
+#include <string>
+
+#include "nixexpr.hh"
+
+namespace nix {
+
+
+struct TraceData {
+    std::string file;
+    const char * type;
+    size_t line;
+    uint64_t id;
+    bool invalid;
+
+    TraceData() : file(""), type(""), line(0), id(0), invalid(true) {}
+    TraceData(Pos p, const char* t);
+    void print(std::ostream & os);
+};
+
+template<typename Data, size_t size>
+struct TracingChunk {
+
+    struct Entry {
+        uint64_t ts_entry;
+        uint64_t ts_exit;
+        Data data;
+    };
+
+
+    struct EntryRAII {
+        Entry* e;
+
+        // Generate a 64bit unsigned integer reprsenting the current
+        // time in nanoseconds
+        static inline uint64_t now() {
+            struct timespec ts;
+
+            clock_gettime(CLOCK_MONOTONIC, &ts);
+            const auto ns = uint64_t(ts.tv_nsec);
+            const auto s = (uint64_t(ts.tv_sec) * 1000000000);
+            return s + ns;
+        }
+
+        EntryRAII(Entry* e, Data d) : e(e) {
+            e->ts_entry = now();
+            e->data = d;
+        }
+
+        ~EntryRAII() {
+            auto n = now();
+            e->ts_exit = n;
+        }
+
+        Entry* operator->() {
+            return e;
+        }
+    };
+
+    Entry data[size];
+    size_t pos;
+
+    TracingChunk(): pos(0) {}
+
+
+    inline bool has_capacity() const {
+        return pos < size - 1;
+    }
+
+    inline EntryRAII create(Data d) {
+        // assert(has_capacity()); -- we are writing C++ to go fast, who cares about correctness?!?
+        auto e = &data[pos++];
+        return EntryRAII(e, d);
+    }
+};
+
+template <typename Data, size_t chunk_size=4096>
+struct TracingBuffer {
+
+    typedef TracingChunk<Data, chunk_size> TC;
+    // Linked-list of all the chunks that we know about, the last chunk in the list is the latest
+    std::list<TC> chunks;
+    TC* current_chunk; // FIXME: undefined before alloc_new_chunk
+
+    TracingBuffer() : current_chunk(NULL) {
+        alloc_next_chunk();
+    }
+
+    inline void alloc_next_chunk() {
+        current_chunk = &chunks.emplace_back(TC());
+    }
+
+    inline typename TC::EntryRAII create(Data d) {
+
+        if (!current_chunk->has_capacity()) [[unlikely]] {
+            alloc_next_chunk();
+        }
+
+        return current_chunk->create(d);
+    }
+};
+
+// FIXME: move this to the header file and the EvalState type so we
+// don't use a global state to do tracing.
+typedef TracingBuffer<TraceData> TracingBufferT;
+
+// RAII container to ensure that exiting the call actually calls the destructor,
+// actual type is std::optional<TracingChunk::EntryRAII>
+#define NIX_TRACE(es, pos, type)                                            \
+  std::optional<TracingBufferT::TC::EntryRAII> __traceRAII = {};               \
+  {                                                                            \
+    if ((es).tracingBuffer) [[unlikely]] {                                     \
+      __traceRAII =                                                            \
+          std::optional((es).tracingBuffer->create(TraceData(pos, type)));  \
+    }                                                                          \
+  }
+
+// create a "trace point" by passing an eval state reference and an expression
+// ptr
+#define NIX_TRACE_ES(es, e) NIX_TRACE((es),(es).positions[(e)->getPos()], (e)->showExprType())
+
+// create a top-level trace-point, for usage within the EvalState class. Assumes
+// `positions` is in scope.
+#define NIX_TRACE_TOP(es,e) NIX_TRACE((es), (es).positions[e->getPos()], "top-level")
+
+}

src/nix-instantiate/nix-instantiate.cc

@@ -81,7 +81,8 @@ void processExpr(EvalState & state, const Strings & attrPaths,
                     if (store2)
                         drvPathS = store2->addPermRoot(drvPath, rootName);
                 }
-                std::cout << fmt("%s%s\n", drvPathS, (outputName != "out" ? "!" + outputName : ""));
+                // THis is polluting the nice trace we're generating, boo.
+                //    std::cout << fmt("%s%s\n", drvPathS, (outputName != "out" ? "!" + outputName : ""));
             }
         }
     }
@@ -190,6 +191,7 @@ static int main_nix_instantiate(int argc, char * * argv)
                 evalOnly, outputKind, xmlOutputSourceLocation, e);
         }
 
+        state->printTraces();
         state->printStats();
 
         return 0;