Merge pull request #3097 from zimbatm/show-traces

function-trace: always show the trace

contrib/stack-collapse.py

@@ -1,12 +1,11 @@
 #!/usr/bin/env nix-shell
 #!nix-shell -i python3 -p python3 --pure
 
-# To be used with `--trace-function-calls` and `-vvvv` and
+# To be used with `--trace-function-calls` and `flamegraph.pl`.
-# `flamegraph.pl`.
 #
 # For example:
 #
-# nix-instantiate --trace-function-calls -vvvv '<nixpkgs>' -A hello 2> nix-function-calls.trace
+# nix-instantiate --trace-function-calls '<nixpkgs>' -A hello 2> nix-function-calls.trace
 # ./contrib/stack-collapse.py nix-function-calls.trace > nix-function-calls.folded
 # nix-shell -p flamegraph --run "flamegraph.pl nix-function-calls.folded > nix-function-calls.svg"
 

src/libexpr/function-trace.hh

@@ -12,13 +12,13 @@ struct FunctionCallTrace
     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());
+        printMsg(lvlInfo, "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());
+        printMsg(lvlInfo, "function-trace exited %1% at %2%", pos, ns.count());
     }
 };
 }

tests/function-trace.sh

@@ -8,7 +8,6 @@ expect_trace() {
     actual=$(
         nix-instantiate \
             --trace-function-calls \
-            -vvvv \
             --expr "$expr" 2>&1 \
             | grep "function-trace" \
             | sed -e 's/ [0-9]*$//'