From e82767910c649f160d6701e47f606f3b8dde4b29 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Sun, 12 Aug 2012 23:29:28 -0400 Subject: [PATCH] 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 '' -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' ... --- src/libexpr/eval.cc | 38 +++++++++++++++++++++++++++++++++++++- src/libexpr/eval.hh | 16 ++++++++++++++-- src/libexpr/nixexpr.hh | 9 +++++++++ src/libexpr/primops.cc | 3 ++- src/libutil/util.hh | 3 +++ 5 files changed, 65 insertions(+), 4 deletions(-) diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index cf7c62ad20..2d41eba0e0 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 PrimOpCalls_; + std::multimap primOpCalls_; + foreach (PrimOpCalls::iterator, i, primOpCalls) + primOpCalls_.insert(std::pair(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 FunctionCalls_; + std::multimap functionCalls_; + foreach (FunctionCalls::iterator, i, functionCalls) + functionCalls_.insert(std::pair(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 AttrSelects_; + std::multimap attrSelects_; + foreach (AttrSelects::iterator, i, attrSelects) + attrSelects_.insert(std::pair(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 5103ae8cef..540f1e200e 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 PrimOpCalls; + PrimOpCalls primOpCalls; + + typedef std::map FunctionCalls; + FunctionCalls functionCalls; + + typedef std::map 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 4c1a0bb2d5..bc6c3287c7 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 0d4efc47e6..b833413ea5 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 edb7c0fa6c..dc38a53ca2 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 = "");