Track function start and end

[grahamc]

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 -vvvvvvv ../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

[edolstra]

Isn't this potentially very expensive since it may do a syscall on the hot path? (I think on Linux the current time is obtained from the vDSO, but on other platforms it might require an actual syscall.)

[grahamc]

I updated it to be conditional on debug logs, changed the log.py to accept a parameter, and replaced :fire: with function-trace.

[grahamc]

I've updated this PR to use the option like you suggested, and also switched to RAII for the trace. I also added the stack collapse script in to ./contrib. I haven't checked how it impacts performance when the option is disabled.

[grahamc]

I'm testing this PR against some particularly complex Nix expressions which the original implementation did not properly trace.

[grahamc]

Yep. It worked great on those test cases. I think this is good to go!

[hamishmack]

The option to use is now --trace-function-calls not -vvvvvvv