Merge pull request #2782 from grahamc/flames

Track function start and end

3 files changed, 34 insertions, 2 deletions

diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc
index d8e10d9f20e1..9f4b6b411a72 100644
--- a/src/libexpr/eval.cc
+++ b/src/libexpr/eval.cc
@@ -9,6 +9,7 @@
 #include "json.hh"
 
 #include <algorithm>
+#include <chrono>
 #include <cstring>
 #include <unistd.h>
 #include <sys/time.h>
@@ -16,7 +17,6 @@
 #include <iostream>
 #include <fstream>
 
-#include <sys/time.h>
 #include <sys/resource.h>
 
 #if HAVE_BOEHMGC
@@ -1094,9 +1094,13 @@ void EvalState::callPrimOp(Value & fun, Value & arg, Value & v, const Pos & pos)
     }
 }
 
-
 void EvalState::callFunction(Value & fun, Value & arg, Value & v, const Pos & pos)
 {
+    std::optional<FunctionCallTrace> trace;
+    if (evalSettings.traceFunctionCalls) {
+        trace.emplace(pos);
+    }
+
     forceValue(fun, pos);
 
     if (fun.type == tPrimOp || fun.type == tPrimOpApp) {
diff --git a/src/libexpr/eval.hh b/src/libexpr/eval.hh
index a314e01e0a71..22472fd726b2 100644
--- a/src/libexpr/eval.hh
+++ b/src/libexpr/eval.hh
@@ -6,6 +6,7 @@
 #include "symbol-table.hh"
 #include "hash.hh"
 #include "config.hh"
+#include "function-trace.hh"
 
 #include <map>
 #include <unordered_map>
@@ -349,6 +350,9 @@ struct EvalSettings : Config
 
     Setting<Strings> allowedUris{this, {}, "allowed-uris",
         "Prefixes of URIs that builtin functions such as fetchurl and fetchGit are allowed to fetch."};
+
+    Setting<bool> traceFunctionCalls{this, false, "trace-function-calls",
+        "Emit log messages for each function entry and exit at the 'vomit' log level (-vvvv)"};
 };
 
 extern EvalSettings evalSettings;
diff --git a/src/libexpr/function-trace.hh b/src/libexpr/function-trace.hh
new file mode 100644
index 000000000000..8234b760312f
--- /dev/null
+++ b/src/libexpr/function-trace.hh
@@ -0,0 +1,24 @@
+#pragma once
+
+#include "eval.hh"
+#include <sys/time.h>
+
+namespace nix {
+
+struct FunctionCallTrace
+{
+    const Pos & pos;
+
+    FunctionCallTrace(const Pos & pos) : pos(pos) {
+        auto duration = std::chrono::high_resolution_clock::now().time_since_epoch();
+        auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(duration);
+        vomit("function-trace entered %1% at %2%", pos, ns.count());
+    }
+
+    ~FunctionCallTrace() {
+        auto duration = std::chrono::high_resolution_clock::now().time_since_epoch();
+        auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(duration);
+        vomit("function-trace exited %1% at %2%", pos, ns.count());
+    }
+};
+}