Merge pull request #2782 from grahamc/flames

Track function start and end
This commit is contained in:
Eelco Dolstra 2019-08-15 14:20:42 +02:00 committed by GitHub
commit 477f82e5a7
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
7 changed files with 189 additions and 3 deletions

39
contrib/stack-collapse.py Executable file
View file

@ -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()

View file

@ -981,6 +981,34 @@ requiredSystemFeatures = [ "kvm" ];
</varlistentry> </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> <varlistentry xml:id="conf-trusted-public-keys"><term><literal>trusted-public-keys</literal></term>
<listitem><para>A whitespace-separated list of public keys. When <listitem><para>A whitespace-separated list of public keys. When

View file

@ -9,6 +9,7 @@
#include "json.hh" #include "json.hh"
#include <algorithm> #include <algorithm>
#include <chrono>
#include <cstring> #include <cstring>
#include <unistd.h> #include <unistd.h>
#include <sys/time.h> #include <sys/time.h>
@ -16,7 +17,6 @@
#include <iostream> #include <iostream>
#include <fstream> #include <fstream>
#include <sys/time.h>
#include <sys/resource.h> #include <sys/resource.h>
#if HAVE_BOEHMGC #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) 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); forceValue(fun, pos);
if (fun.type == tPrimOp || fun.type == tPrimOpApp) { if (fun.type == tPrimOp || fun.type == tPrimOpApp) {

View file

@ -6,6 +6,7 @@
#include "symbol-table.hh" #include "symbol-table.hh"
#include "hash.hh" #include "hash.hh"
#include "config.hh" #include "config.hh"
#include "function-trace.hh"
#include <map> #include <map>
#include <unordered_map> #include <unordered_map>
@ -349,6 +350,9 @@ struct EvalSettings : Config
Setting<Strings> allowedUris{this, {}, "allowed-uris", Setting<Strings> allowedUris{this, {}, "allowed-uris",
"Prefixes of URIs that builtin functions such as fetchurl and fetchGit are allowed to fetch."}; "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; extern EvalSettings evalSettings;

View file

@ -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());
}
};
}

86
tests/function-trace.sh Executable file
View file

@ -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

View file

@ -29,7 +29,8 @@ nix_tests = \
plugins.sh \ plugins.sh \
search.sh \ search.sh \
nix-copy-ssh.sh \ nix-copy-ssh.sh \
post-hook.sh post-hook.sh \
function-trace.sh
# parallel.sh # parallel.sh
install-tests += $(foreach x, $(nix_tests), tests/$(x)) install-tests += $(foreach x, $(nix_tests), tests/$(x))