diff options
| -rwxr-xr-x | contrib/stack-collapse.py | 39 | ||||
| -rw-r--r-- | doc/manual/command-ref/conf-file.xml | 28 | ||||
| -rw-r--r-- | src/libexpr/eval.cc | 8 | ||||
| -rw-r--r-- | src/libexpr/eval.hh | 4 | ||||
| -rw-r--r-- | src/libexpr/function-trace.hh | 24 | ||||
| -rwxr-xr-x | tests/function-trace.sh | 86 | ||||
| -rw-r--r-- | tests/local.mk | 3 |
7 files changed, 189 insertions, 3 deletions
diff --git a/contrib/stack-collapse.py b/contrib/stack-collapse.py new file mode 100755 index 000000000000..ee77e158945c --- /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 '<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" + +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 1325a3f22253..320e15339d9e 100644 --- a/doc/manual/command-ref/conf-file.xml +++ b/doc/manual/command-ref/conf-file.xml @@ -981,6 +981,34 @@ requiredSystemFeatures = [ "kvm" ]; </varlistentry> + <varlistentry xml:id="conf-trace-function-calls"><term><literal>trace-function-calls</literal></term> + + <listitem> + + <para>Default: <literal>false</literal>.</para> + + <para>If set to <literal>true</literal>, 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.</para> + + <informalexample><screen> +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 +</screen></informalexample> + + <para>The <literal>undefined position</literal> means the function + call is a builtin.</para> + + <para>Use the <literal>contrib/stack-collapse.py</literal> script + distributed with the Nix source code to convert the trace logs + in to a format suitable for <command>flamegraph.pl</command>.</para> + + </listitem> + + </varlistentry> + <varlistentry xml:id="conf-trusted-public-keys"><term><literal>trusted-public-keys</literal></term> <listitem><para>A whitespace-separated list of public keys. When 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()); + } +}; +} diff --git a/tests/function-trace.sh b/tests/function-trace.sh new file mode 100755 index 000000000000..f7d93b4356e5 --- /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 ef359c631d62..187f96ea2069 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)) |