mirror of
https://github.com/privatevoid-net/nix-super.git
synced 2024-11-22 14:06:16 +02:00
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.
This commit is contained in:
parent
1eeaf99cf8
commit
ee9c988a1b
7 changed files with 189 additions and 3 deletions
39
contrib/stack-collapse.py
Executable file
39
contrib/stack-collapse.py
Executable 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()
|
|
@ -973,6 +973,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
|
||||||
|
|
|
@ -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) {
|
||||||
|
|
|
@ -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;
|
||||||
|
|
24
src/libexpr/function-trace.hh
Normal file
24
src/libexpr/function-trace.hh
Normal 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
86
tests/function-trace.sh
Executable 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
|
|
@ -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))
|
||||||
|
|
Loading…
Reference in a new issue