about summary refs log tree commit diff
diff options
context:
space:
mode:
Diffstat
-rwxr-xr-xcontrib/stack-collapse.py39
-rw-r--r--doc/manual/command-ref/conf-file.xml36
-rw-r--r--src/libexpr/eval.cc8
-rw-r--r--src/libexpr/eval.hh4
-rw-r--r--src/libexpr/function-trace.hh24
-rw-r--r--src/libstore/download.cc4
-rw-r--r--src/libstore/download.hh3
-rw-r--r--src/libstore/pathlocks.cc1
-rwxr-xr-xtests/function-trace.sh86
-rw-r--r--tests/local.mk3
-rw-r--r--tests/post-hook.sh2
-rwxr-xr-xtests/push-to-store.sh (renamed from tests/push_to_store.sh)0
12 files changed, 203 insertions, 7 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 c7b540892f9a..320e15339d9e 100644
--- a/doc/manual/command-ref/conf-file.xml
+++ b/doc/manual/command-ref/conf-file.xml
@@ -873,6 +873,14 @@ password <replaceable>my-password</replaceable>
 
   </varlistentry>
 
+  <varlistentry xml:id="conf-stalled-download-timeout"><term><literal>stalled-download-timeout</literal></term>
+    <listitem>
+      <para>The timeout (in seconds) for receiving data from servers
+      during download. Nix cancels idle downloads after this timeout's
+      duration.</para>
+    </listitem>
+  </varlistentry>
+
   <varlistentry xml:id="conf-substituters"><term><literal>substituters</literal></term>
 
     <listitem><para>A list of URLs of substituters, separated by
@@ -973,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/src/libstore/download.cc b/src/libstore/download.cc
index 91087eebcfcb..c322d267d4f2 100644
--- a/src/libstore/download.cc
+++ b/src/libstore/download.cc
@@ -236,8 +236,6 @@ struct CurlDownloader : public Downloader
             return ((DownloadItem *) userp)->readCallback(buffer, size, nitems);
         }
 
-        long lowSpeedTimeout = 300;
-
         void init()
         {
             if (!req) req = curl_easy_init();
@@ -297,7 +295,7 @@ struct CurlDownloader : public Downloader
             curl_easy_setopt(req, CURLOPT_CONNECTTIMEOUT, downloadSettings.connectTimeout.get());
 
             curl_easy_setopt(req, CURLOPT_LOW_SPEED_LIMIT, 1L);
-            curl_easy_setopt(req, CURLOPT_LOW_SPEED_TIME, lowSpeedTimeout);
+            curl_easy_setopt(req, CURLOPT_LOW_SPEED_TIME, downloadSettings.stalledDownloadTimeout.get());
 
             /* If no file exist in the specified path, curl continues to work
                anyway as if netrc support was disabled. */
diff --git a/src/libstore/download.hh b/src/libstore/download.hh
index 3b7fff3ba4cb..c68381846948 100644
--- a/src/libstore/download.hh
+++ b/src/libstore/download.hh
@@ -24,6 +24,9 @@ struct DownloadSettings : Config
     Setting<unsigned long> connectTimeout{this, 0, "connect-timeout",
         "Timeout for connecting to servers during downloads. 0 means use curl's builtin default."};
 
+    Setting<unsigned long> stalledDownloadTimeout{this, 300, "stalled-download-timeout",
+        "Timeout (in seconds) for receiving data from servers during download. Nix cancels idle downloads after this timeout's duration."};
+
     Setting<unsigned int> tries{this, 5, "download-attempts",
         "How often Nix will attempt to download a file before giving up."};
 };
diff --git a/src/libstore/pathlocks.cc b/src/libstore/pathlocks.cc
index b6d8547c70e6..2635e3940af8 100644
--- a/src/libstore/pathlocks.cc
+++ b/src/libstore/pathlocks.cc
@@ -5,6 +5,7 @@
 #include <cerrno>
 #include <cstdlib>
 
+#include <fcntl.h>
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <sys/file.h>
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))
diff --git a/tests/post-hook.sh b/tests/post-hook.sh
index 3f82d0c5e662..a026572154db 100644
--- a/tests/post-hook.sh
+++ b/tests/post-hook.sh
@@ -5,7 +5,7 @@ clearStore
 export REMOTE_STORE=$TEST_ROOT/remote_store
 
 # Build the dependencies and push them to the remote store
-nix-build dependencies.nix --post-build-hook $PWD/push_to_store.sh
+nix-build -o $TEST_ROOT/result dependencies.nix --post-build-hook $PWD/push-to-store.sh
 
 clearStore
 
diff --git a/tests/push_to_store.sh b/tests/push-to-store.sh
index d97eb095dd74..d97eb095dd74 100755
--- a/tests/push_to_store.sh
+++ b/tests/push-to-store.sh
generated by cgit-pink 1.4.1 (git 2.44.2) at 2025-01-19T04ยท33+0000