From ee9c988a1b2e3c511b8613e698a0f9632ab1538f Mon Sep 17 00:00:00 2001 From: Graham Christensen Date: Fri, 12 Apr 2019 12:31:33 -0400 Subject: [PATCH] Track function start and ends for flame graphs With this patch, and this file I called `log.py`: #!/usr/bin/env nix-shell #!nix-shell -i python3 -p python3 --pure import sys from pprint import pprint stack = [] timestack = [] for line in open(sys.argv[1]): components = line.strip().split(" ", 2) if components[0] != "function-trace": continue direction = components[1] components = components[2].rsplit(" ", 2) loc = components[0] _at = components[1] time = int(components[2]) if direction == "entered": stack.append(loc) timestack.append(time) elif direction == "exited": dur = time - timestack.pop() vst = ";".join(stack) print(f"{vst} {dur}") stack.pop() and: nix-instantiate --trace-function-calls -vvvv ../nixpkgs/pkgs/top-level/release.nix -A unstable > log.matthewbauer 2>&1 ./log.py ./log.matthewbauer > log.matthewbauer.folded flamegraph.pl --title matthewbauer-post-pr log.matthewbauer.folded > log.matthewbauer.folded.svg I can make flame graphs like: http://gsc.io/log.matthewbauer.folded.svg --- Includes test cases around function call failures and tryEval. Uses RAII so the finish is always called at the end of the function. --- contrib/stack-collapse.py | 39 +++++++++++++ doc/manual/command-ref/conf-file.xml | 28 +++++++++ src/libexpr/eval.cc | 8 ++- src/libexpr/eval.hh | 4 ++ src/libexpr/function-trace.hh | 24 ++++++++ tests/function-trace.sh | 86 ++++++++++++++++++++++++++++ tests/local.mk | 3 +- 7 files changed, 189 insertions(+), 3 deletions(-) create mode 100755 contrib/stack-collapse.py create mode 100644 src/libexpr/function-trace.hh create mode 100755 tests/function-trace.sh diff --git a/contrib/stack-collapse.py b/contrib/stack-collapse.py new file mode 100755 index 00000000000..ee77e158945 --- /dev/null +++ b/contrib/stack-collapse.py @@ -0,0 +1,39 @@ +#!/usr/bin/env nix-shell +#!nix-shell -i python3 -p python3 --pure + +# To be used with `--trace-function-calls` and `-vvvv` and +# `flamegraph.pl`. +# +# For example: +# +# nix-instantiate --trace-function-calls -vvvv '' -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" + +import sys +from pprint import pprint +import fileinput + +stack = [] +timestack = [] + +for line in fileinput.input(): + components = line.strip().split(" ", 2) + if components[0] != "function-trace": + continue + + direction = components[1] + components = components[2].rsplit(" ", 2) + + loc = components[0] + _at = components[1] + time = int(components[2]) + + if direction == "entered": + stack.append(loc) + timestack.append(time) + elif direction == "exited": + dur = time - timestack.pop() + vst = ";".join(stack) + print(f"{vst} {dur}") + stack.pop() diff --git a/doc/manual/command-ref/conf-file.xml b/doc/manual/command-ref/conf-file.xml index c7b540892f9..407e5d10b6a 100644 --- a/doc/manual/command-ref/conf-file.xml +++ b/doc/manual/command-ref/conf-file.xml @@ -973,6 +973,34 @@ requiredSystemFeatures = [ "kvm" ]; + trace-function-calls + + + + Default: false. + + If set to true, the Nix evaluator will + trace every function call. Nix will print a log message at the + "vomit" level for every function entrance and function exit. + + +function-trace entered undefined position at 1565795816999559622 +function-trace exited undefined position at 1565795816999581277 +function-trace entered /nix/store/.../example.nix:226:41 at 1565795253249935150 +function-trace exited /nix/store/.../example.nix:226:41 at 1565795253249941684 + + + The undefined position means the function + call is a builtin. + + Use the contrib/stack-collapse.py script + distributed with the Nix source code to convert the trace logs + in to a format suitable for flamegraph.pl. + + + + + trusted-public-keys A whitespace-separated list of public keys. When diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index d8e10d9f20e..9f4b6b411a7 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -9,6 +9,7 @@ #include "json.hh" #include +#include #include #include #include @@ -16,7 +17,6 @@ #include #include -#include #include #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 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 a314e01e0a7..22472fd726b 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 #include @@ -349,6 +350,9 @@ struct EvalSettings : Config Setting allowedUris{this, {}, "allowed-uris", "Prefixes of URIs that builtin functions such as fetchurl and fetchGit are allowed to fetch."}; + + Setting 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 00000000000..8234b760312 --- /dev/null +++ b/src/libexpr/function-trace.hh @@ -0,0 +1,24 @@ +#pragma once + +#include "eval.hh" +#include + +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(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(duration); + vomit("function-trace exited %1% at %2%", pos, ns.count()); + } +}; +} diff --git a/tests/function-trace.sh b/tests/function-trace.sh new file mode 100755 index 00000000000..f7d93b4356e --- /dev/null +++ b/tests/function-trace.sh @@ -0,0 +1,86 @@ +source common.sh + +set +x + +expect_trace() { + expr="$1" + expect="$2" + actual=$( + nix-instantiate \ + --trace-function-calls \ + -vvvv \ + --expr "$expr" 2>&1 \ + | grep "function-trace" \ + | sed -e 's/ [0-9]*$//' + ); + + echo -n "Tracing expression '$expr'" + set +e + msg=$(diff -swB \ + <(echo "$expect") \ + <(echo "$actual") + ); + result=$? + set -e + if [ $result -eq 0 ]; then + echo " ok." + else + echo " failed. difference:" + echo "$msg" + return $result + fi +} + +# failure inside a tryEval +expect_trace 'builtins.tryEval (throw "example")' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace entered (string):1:19 at +function-trace exited (string):1:19 at +function-trace exited (string):1:1 at +" + +# Missing argument to a formal function +expect_trace '({ x }: x) { }' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +" + +# Too many arguments to a formal function +expect_trace '({ x }: x) { x = "x"; y = "y"; }' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +" + +# Not enough arguments to a lambda +expect_trace '(x: y: x + y) 1' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +" + +# Too many arguments to a lambda +expect_trace '(x: x) 1 2' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +" + +# Not a function +expect_trace '1 2' " +function-trace entered undefined position at +function-trace exited undefined position at +function-trace entered (string):1:1 at +function-trace exited (string):1:1 at +" + +set -e diff --git a/tests/local.mk b/tests/local.mk index ef359c631d6..187f96ea206 100644 --- a/tests/local.mk +++ b/tests/local.mk @@ -29,7 +29,8 @@ nix_tests = \ plugins.sh \ search.sh \ nix-copy-ssh.sh \ - post-hook.sh + post-hook.sh \ + function-trace.sh # parallel.sh install-tests += $(foreach x, $(nix_tests), tests/$(x))