Add some basic profiling support to the evaluator

Setting the environment variable NIX_COUNT_CALLS to 1 enables some
basic profiling in the evaluator.  It will count calls to functions
and primops as well as evaluations of attributes.

For example, to see where evaluation of a NixOS configuration spends
its time:

$ NIX_SHOW_STATS=1 NIX_COUNT_CALLS=1 ./src/nix-instantiate/nix-instantiate '<nixos>' -A system --readonly-mode
...
calls to 39 primops:
    239532 head
    233962 tail
    191252 hasAttr
...
calls to 1595 functions:
    224157 `/nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs/pkgs/lib/lists.nix:17:19'
    221767 `/nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs/pkgs/lib/lists.nix:17:14'
    221767 `/nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs/pkgs/lib/lists.nix:17:10'
...
evaluations of 7088 attributes:
    167377 undefined position
    132459 `/nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs/pkgs/lib/attrsets.nix:119:41'
     47322 `/nix/var/nix/profiles/per-user/root/channels/nixos/nixpkgs/pkgs/lib/attrsets.nix:13:21'
...

5 files changed, 65 insertions, 4 deletions

diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc
index cf7c62ad2..2d41eba0e 100644
--- a/src/libexpr/eval.cc
+++ b/src/libexpr/eval.cc
@@ -144,6 +144,7 @@ EvalState::EvalState()
 {
     nrEnvs = nrValuesInEnvs = nrValues = nrListElems = 0;
     nrAttrsets = nrOpUpdates = nrOpUpdateValuesCopied = 0;
+    countCalls = getEnv("NIX_COUNT_CALLS", "0") != "0";
 
 #if HAVE_BOEHMGC
     static bool gcInitialised = true;
@@ -300,8 +301,10 @@ inline Value * EvalState::lookupVar(Env * env, const VarRef & var)
     if (var.fromWith) {
         while (1) {
             Bindings::iterator j = env->values[0]->attrs->find(var.name);
-            if (j != env->values[0]->attrs->end())
+            if (j != env->values[0]->attrs->end()) {
+                if (countCalls && j->pos) attrSelects[*j->pos]++;
                 return j->value;
+            }
             if (env->prevWith == 0)
                 throwEvalError("undefined variable `%1%'", var.name);
             for (unsigned int l = env->prevWith; l; --l, env = env->up) ;
@@ -619,8 +622,10 @@ void ExprSelect::eval(EvalState & state, Env & env, Value & v)
             }
             vAttrs = j->value;
             pos = j->pos;
+            if (state.countCalls && pos) state.attrSelects[*pos]++;
         }
     
+
         state.forceValue(*vAttrs);
         
     } catch (Error & e) {
@@ -700,6 +705,7 @@ void EvalState::callFunction(Value & fun, Value & arg, Value & v)
                 vArgs[n--] = arg->primOpApp.right;
 
             /* And call the primop. */
+            if (countCalls) primOpCalls[primOp->primOp->name]++;
             try {
                 primOp->primOp->fun(*this, vArgs, v);
             } catch (Error & e) {
@@ -760,6 +766,8 @@ void EvalState::callFunction(Value & fun, Value & arg, Value & v)
             throwTypeError("function at %1% called with unexpected argument", fun.lambda.fun->pos);
     }
 
+    if (countCalls) functionCalls[fun.lambda.fun->pos]++;
+
     try {
         fun.lambda.fun->body->eval(*this, env2, v);
     } catch (Error & e) {
@@ -1216,6 +1224,34 @@ void EvalState::printStats()
     printMsg(v, format("  number of thunks: %1%") % nrThunks);
     printMsg(v, format("  number of thunks avoided: %1%") % nrAvoided);
     printMsg(v, format("  number of attr lookups: %1%") % nrLookups);
+
+    if (countCalls) {
+
+        printMsg(v, format("calls to %1% primops:") % primOpCalls.size());
+        typedef std::multimap<unsigned int, Symbol> PrimOpCalls_;
+        std::multimap<unsigned int, Symbol> primOpCalls_;
+        foreach (PrimOpCalls::iterator, i, primOpCalls)
+            primOpCalls_.insert(std::pair<unsigned int, Symbol>(i->second, i->first));
+        foreach_reverse (PrimOpCalls_::reverse_iterator, i, primOpCalls_)
+            printMsg(v, format("%1$10d %2%") % i->first % i->second);
+
+        printMsg(v, format("calls to %1% functions:") % functionCalls.size());
+        typedef std::multimap<unsigned int, Pos> FunctionCalls_;
+        std::multimap<unsigned int, Pos> functionCalls_;
+        foreach (FunctionCalls::iterator, i, functionCalls)
+            functionCalls_.insert(std::pair<unsigned int, Pos>(i->second, i->first));
+        foreach_reverse (FunctionCalls_::reverse_iterator, i, functionCalls_)
+            printMsg(v, format("%1$10d %2%") % i->first % i->second);
+
+        printMsg(v, format("evaluations of %1% attributes:") % attrSelects.size());
+        typedef std::multimap<unsigned int, Pos> AttrSelects_;
+        std::multimap<unsigned int, Pos> attrSelects_;
+        foreach (AttrSelects::iterator, i, attrSelects)
+            attrSelects_.insert(std::pair<unsigned int, Pos>(i->second, i->first));
+        foreach_reverse (AttrSelects_::reverse_iterator, i, attrSelects_)
+            printMsg(v, format("%1$10d %2%") % i->first % i->second);
+
+    }
 }
 
 
diff --git a/src/libexpr/eval.hh b/src/libexpr/eval.hh
index 5103ae8ce..540f1e200 100644
--- a/src/libexpr/eval.hh
+++ b/src/libexpr/eval.hh
@@ -244,9 +244,21 @@ private:
     unsigned long nrAttrsets;
     unsigned long nrOpUpdates;
     unsigned long nrOpUpdateValuesCopied;
-    
-    friend class RecursionCounter;
+
+    bool countCalls;
+
+    typedef std::map<Symbol, unsigned int> PrimOpCalls;
+    PrimOpCalls primOpCalls;
+
+    typedef std::map<Pos, unsigned int> FunctionCalls;
+    FunctionCalls functionCalls;
+
+    typedef std::map<Pos, unsigned int> AttrSelects;
+    AttrSelects attrSelects;
+
     friend class ExprOpUpdate;
+    friend class ExprSelect;
+    friend void prim_getAttr(EvalState & state, Value * * args, Value & v);
 };
 
 
diff --git a/src/libexpr/nixexpr.hh b/src/libexpr/nixexpr.hh
index 4c1a0bb2d..bc6c3287c 100644
--- a/src/libexpr/nixexpr.hh
+++ b/src/libexpr/nixexpr.hh
@@ -27,6 +27,15 @@ struct Pos
     Pos() : line(0), column(0) { };
     Pos(const string & file, unsigned int line, unsigned int column)
         : file(file), line(line), column(column) { };
+    bool operator < (const Pos & p2) const
+    {
+        int d = file.compare(p2.file);
+        if (d < 0) return true;
+        if (d > 0) return false;
+        if (line < p2.line) return true;
+        if (line > p2.line) return false;
+        return column < p2.column;
+    }
 };
 
 extern Pos noPos;
diff --git a/src/libexpr/primops.cc b/src/libexpr/primops.cc
index 0d4efc47e..b833413ea 100644
--- a/src/libexpr/primops.cc
+++ b/src/libexpr/primops.cc
@@ -713,7 +713,7 @@ static void prim_attrNames(EvalState & state, Value * * args, Value & v)
 
 
 /* Dynamic version of the `.' operator. */
-static void prim_getAttr(EvalState & state, Value * * args, Value & v)
+void prim_getAttr(EvalState & state, Value * * args, Value & v)
 {
     string attr = state.forceStringNoCtx(*args[0]);
     state.forceAttrs(*args[1]);
@@ -722,6 +722,7 @@ static void prim_getAttr(EvalState & state, Value * * args, Value & v)
     if (i == args[1]->attrs->end())
         throw EvalError(format("attribute `%1%' missing") % attr);
     // !!! add to stack trace?
+    if (state.countCalls && i->pos) state.attrSelects[*i->pos]++;
     state.forceValue(*i->value);
     v = *i->value;
 }
diff --git a/src/libutil/util.hh b/src/libutil/util.hh
index edb7c0fa6..dc38a53ca 100644
--- a/src/libutil/util.hh
+++ b/src/libutil/util.hh
@@ -17,6 +17,9 @@ namespace nix {
 #define foreach(it_type, it, collection)                                \
     for (it_type it = (collection).begin(); it != (collection).end(); ++it)
 
+#define foreach_reverse(it_type, it, collection)                                \
+    for (it_type it = (collection).rbegin(); it != (collection).rend(); ++it)
+
 
 /* Return an environment variable. */
 string getEnv(const string & key, const string & def = "");