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.

1 files changed, 86 insertions, 0 deletions

diff --git a/tests/function-trace.sh b/tests/function-trace.sh
new file mode 100755
index 000000000..f7d93b435
--- /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