* Turned the msg() and debug() functions into macros, since they

  turned out to be a huge performance bottleneck (the text to printed
  would always be evaluated, even when it was above the verbosity
  level).  This reduces fix-ng execution time by over 50%.

  gprof(1) is very useful. :-)

10 files changed, 60 insertions, 45 deletions

diff --git a/src/fix-ng/eval.cc b/src/fix-ng/eval.cc
index 8e10caa843ac..2b45b47984e8 100644
--- a/src/fix-ng/eval.cc
+++ b/src/fix-ng/eval.cc
@@ -23,7 +23,6 @@ static Expr substArgs(Expr body, ATermList formals, Expr arg)
     while (!ATisEmpty(formals)) {
         ATerm t = ATgetFirst(formals);
         Expr name, def;
-        debug(printTerm(t));
         if (ATmatch(t, "NoDefFormal(<term>)", &name))
             subs.set(name, undefined);
         else if (ATmatch(t, "DefFormal(<term>, <term>)", &name, &def))
@@ -234,7 +233,8 @@ Expr evalExpr2(EvalState & state, Expr e)
 
 Expr evalExpr(EvalState & state, Expr e)
 {
-    Nest nest(lvlVomit, format("evaluating expression: %1%") % printTerm(e));
+    startNest(nest, lvlVomit,
+        format("evaluating expression: %1%") % printTerm(e));
 
     state.nrEvaluated++;
 
@@ -258,7 +258,7 @@ Expr evalExpr(EvalState & state, Expr e)
 
 Expr evalFile(EvalState & state, const Path & path)
 {
-    Nest nest(lvlTalkative, format("evaluating file `%1%'") % path);
+    startNest(nest, lvlTalkative, format("evaluating file `%1%'") % path);
     Expr e = parseExprFromFile(path);
     return evalExpr(state, e);
 }
diff --git a/src/fix-ng/fix.cc b/src/fix-ng/fix.cc
index c24ca4d9c4da..dc2790a60ad9 100644
--- a/src/fix-ng/fix.cc
+++ b/src/fix-ng/fix.cc
@@ -60,7 +60,7 @@ static Expr evalExpr2(EvalState & state, Expr e)
 
 static Expr evalStdin(EvalState & state)
 {
-    Nest nest(lvlTalkative, format("evaluating standard input"));
+    startNest(nest, lvlTalkative, format("evaluating standard input"));
     Expr e = ATreadFromFile(stdin);
     if (!e) 
         throw Error(format("unable to read a term from stdin"));
diff --git a/src/fix-ng/primops.cc b/src/fix-ng/primops.cc
index fb923ed46e5c..07281e89beaf 100644
--- a/src/fix-ng/primops.cc
+++ b/src/fix-ng/primops.cc
@@ -58,7 +58,7 @@ static Path copyAtom(EvalState & state, const Path & srcPath)
     Path drvPath = writeTerm(unparseNixExpr(ne), "");
     state.drvHashes[drvPath] = drvHash;
 
-    msg(lvlChatty, format("copied `%1%' -> closure `%2%'")
+    printMsg(lvlChatty, format("copied `%1%' -> closure `%2%'")
         % srcPath % drvPath);
     return drvPath;
 }
@@ -107,7 +107,7 @@ static string processBinding(EvalState & state, Expr e, NixExpr & ne)
 	string s;
 	bool first = true;
         while (!ATisEmpty(es)) {
-            Nest nest(lvlVomit, format("processing list element"));
+            startNest(nest, lvlVomit, format("processing list element"));
 	    if (!first) s = s + " "; else first = false;
 	    s += processBinding(state, evalExpr(state, ATgetFirst(es)), ne);
             es = ATgetNext(es);
@@ -123,7 +123,7 @@ static string processBinding(EvalState & state, Expr e, NixExpr & ne)
 
 Expr primDerivation(EvalState & state, Expr args)
 {
-    Nest nest(lvlVomit, "evaluating derivation");
+    startNest(nest, lvlVomit, "evaluating derivation");
 
     ATermMap attrs;
     args = evalExpr(state, args);
@@ -143,7 +143,7 @@ Expr primDerivation(EvalState & state, Expr args)
     {
         string key = aterm2String(ATgetFirst(keys));
         Expr value = attrs.get(key);
-        Nest nest(lvlVomit, format("processing attribute `%1%'") % key);
+        startNest(nest, lvlVomit, format("processing attribute `%1%'") % key);
 
         /* The `args' attribute is special: it supplies the
            command-line arguments to the builder. */
@@ -199,7 +199,7 @@ Expr primDerivation(EvalState & state, Expr args)
     Path drvPath = writeTerm(unparseNixExpr(ne), "-d-" + drvName);
     state.drvHashes[drvPath] = drvHash;
 
-    msg(lvlChatty, format("instantiated `%1%' -> `%2%'")
+    printMsg(lvlChatty, format("instantiated `%1%' -> `%2%'")
         % drvName % drvPath);
 
     attrs.set("outPath", ATmake("Path(<str>)", outPath.c_str()));
diff --git a/src/fix/fix.cc b/src/fix/fix.cc
index 9a8ff1513042..d75e26b00930 100644
--- a/src/fix/fix.cc
+++ b/src/fix/fix.cc
@@ -273,7 +273,7 @@ static Expr evalExpr2(EvalState & state, Expr e)
         Path pkgPath = writeTerm(unparseNixExpr(ne), "");
         state.pkgHashes[pkgPath] = pkgHash;
 
-        msg(lvlChatty, format("copied `%1%' -> closure `%2%'")
+        printMsg(lvlChatty, format("copied `%1%' -> closure `%2%'")
             % srcPath % pkgPath);
 
         return ATmake("NixExpr(<str>)", pkgPath.c_str());
@@ -362,7 +362,7 @@ static Expr evalExpr2(EvalState & state, Expr e)
         Path pkgPath = writeTerm(unparseNixExpr(ne), "-d-" + name);
         state.pkgHashes[pkgPath] = pkgHash;
 
-        msg(lvlChatty, format("instantiated `%1%' -> `%2%'")
+        printMsg(lvlChatty, format("instantiated `%1%' -> `%2%'")
             % name % pkgPath);
 
         return ATmake("NixExpr(<str>)", pkgPath.c_str());
@@ -383,7 +383,8 @@ static Expr evalExpr2(EvalState & state, Expr e)
 
 static Expr evalExpr(EvalState & state, Expr e)
 {
-    Nest nest(lvlVomit, format("evaluating expression: %1%") % printTerm(e));
+    startNest(nest, lvlVomit,
+        format("evaluating expression: %1%") % printTerm(e));
 
     /* Consult the memo table to quickly get the normal form of
        previously evaluated expressions. */
@@ -405,7 +406,7 @@ static Expr evalExpr(EvalState & state, Expr e)
 static Expr evalFile(EvalState & state, const Path & relPath)
 {
     Path path = searchPath(state.searchDirs, relPath);
-    Nest nest(lvlTalkative, format("evaluating file `%1%'") % path);
+    startNest(nest, lvlTalkative, format("evaluating file `%1%'") % path);
     Expr e = ATreadFromNamedFile(path.c_str());
     if (!e) 
         throw Error(format("unable to read a term from `%1%'") % path);
@@ -415,7 +416,7 @@ static Expr evalFile(EvalState & state, const Path & relPath)
 
 static Expr evalStdin(EvalState & state)
 {
-    Nest nest(lvlTalkative, format("evaluating standard input"));
+    startNest(nest, lvlTalkative, format("evaluating standard input"));
     Expr e = ATreadFromFile(stdin);
     if (!e) 
         throw Error(format("unable to read a term from stdin"));
diff --git a/src/libmain/shared.cc b/src/libmain/shared.cc
index 39439f8e1921..b06f5eb8b465 100644
--- a/src/libmain/shared.cc
+++ b/src/libmain/shared.cc
@@ -64,17 +64,17 @@ int main(int argc, char * * argv)
     try {
         initAndRun(argc, argv);
     } catch (UsageError & e) {
-        msg(lvlError, 
+        printMsg(lvlError, 
             format(
                 "error: %1%\n"
                 "Try `%2% --help' for more information.")
             % e.what() % programId);
         return 1;
     } catch (Error & e) {
-        msg(lvlError, format("error: %1%") % e.msg());
+        printMsg(lvlError, format("error: %1%") % e.msg());
         return 1;
     } catch (exception & e) {
-        msg(lvlError, format("error: %1%") % e.what());
+        printMsg(lvlError, format("error: %1%") % e.what());
         return 1;
     }
 
diff --git a/src/libnix/db.cc b/src/libnix/db.cc
index c498fab74851..63ec2724fcb3 100644
--- a/src/libnix/db.cc
+++ b/src/libnix/db.cc
@@ -202,7 +202,8 @@ void Database::open(const string & path)
                 setAccessorCount(fdAccessors, 1);
 
             if (n != 0) {
-                msg(lvlTalkative, format("accessor count is %1%, running recovery") % n);
+                printMsg(lvlTalkative,
+                    format("accessor count is %1%, running recovery") % n);
 
                 /* Open the environment after running recovery. */
                 openEnv(env, path, DB_RECOVER);
diff --git a/src/libnix/exec.cc b/src/libnix/exec.cc
index 00d9e6a0ac03..47a385f147d5 100644
--- a/src/libnix/exec.cc
+++ b/src/libnix/exec.cc
@@ -110,7 +110,7 @@ void runProgram(const string & program,
     
     if (!WIFEXITED(status) || WEXITSTATUS(status) != 0) {
 	if (keepFailed) {
-	    msg(lvlTalkative, 
+	    printMsg(lvlTalkative, 
 		format("program `%1%' failed; keeping build directory `%2%'")
                 % program % tmpDir);
 	    delTmpDir.cancel();
diff --git a/src/libnix/normalise.cc b/src/libnix/normalise.cc
index d3978ac2c159..49f86cc6fe18 100644
--- a/src/libnix/normalise.cc
+++ b/src/libnix/normalise.cc
@@ -20,7 +20,7 @@ static Path useSuccessor(const Path & path)
 
 Path normaliseNixExpr(const Path & _nePath, PathSet pending)
 {
-    Nest nest(lvlTalkative,
+    startNest(nest, lvlTalkative,
         format("normalising expression in `%1%'") % (string) _nePath);
 
     /* Try to substitute the expression by any known successors in
@@ -156,13 +156,13 @@ Path normaliseNixExpr(const Path & _nePath, PathSet pending)
         }
 
         /* Run the builder. */
-        msg(lvlChatty, format("building..."));
+        printMsg(lvlChatty, format("building..."));
         runProgram(ne.derivation.builder, ne.derivation.args, env,
             nixLogDir + "/" + baseNameOf(nePath));
-        msg(lvlChatty, format("build completed"));
+        printMsg(lvlChatty, format("build completed"));
         
     } else
-        msg(lvlChatty, format("fast build succesful"));
+        printMsg(lvlChatty, format("fast build succesful"));
 
     /* Check whether the output paths were created, and grep each
        output path to determine what other paths it references.  Also make all
@@ -239,7 +239,7 @@ Path normaliseNixExpr(const Path & _nePath, PathSet pending)
     /* Write the normal form.  This does not have to occur in the
        transaction below because writing terms is idem-potent. */
     ATerm nfTerm = unparseNixExpr(nf);
-    msg(lvlVomit, format("normal form: %1%") % printTerm(nfTerm));
+    printMsg(lvlVomit, format("normal form: %1%") % printTerm(nfTerm));
     Path nfPath = writeTerm(nfTerm, "-s");
 
     /* Register each outpat path, and register the normal form.  This
@@ -262,7 +262,7 @@ Path normaliseNixExpr(const Path & _nePath, PathSet pending)
 
 void realiseClosure(const Path & nePath, PathSet pending)
 {
-    Nest nest(lvlDebug, format("realising closure `%1%'") % nePath);
+    startNest(nest, lvlDebug, format("realising closure `%1%'") % nePath);
 
     NixExpr ne = exprFromPath(nePath, pending);
     if (ne.type != NixExpr::neClosure)
@@ -290,7 +290,7 @@ void ensurePath(const Path & path, PathSet pending)
             if (isValidPath(path)) return;
             throw Error(format("substitute failed to produce expected output path"));
         } catch (Error & e) {
-            msg(lvlTalkative, 
+            printMsg(lvlTalkative, 
                 format("building of substitute `%1%' for `%2%' failed: %3%")
                 % *i % path % e.what());
         }
diff --git a/src/libnix/util.cc b/src/libnix/util.cc
index 016ee991a45c..299a37f6c877 100644
--- a/src/libnix/util.cc
+++ b/src/libnix/util.cc
@@ -110,7 +110,7 @@ bool pathExists(const Path & path)
 
 void deletePath(const Path & path)
 {
-    msg(lvlVomit, format("deleting path `%1%'") % path);
+    printMsg(lvlVomit, format("deleting path `%1%'") % path);
 
     struct stat st;
     if (lstat(path.c_str(), &st))
@@ -194,15 +194,9 @@ Verbosity verbosity = lvlError;
 static int nestingLevel = 0;
 
 
-Nest::Nest(Verbosity level, const format & f)
+Nest::Nest()
 {
-    if (level > verbosity)
-        nest = false;
-    else {
-        msg(level, f);
-        nest = true;
-        nestingLevel++;
-    }
+    nest = false;
 }
 
 
@@ -212,7 +206,17 @@ Nest::~Nest()
 }
 
 
-void msg(Verbosity level, const format & f)
+void Nest::open(Verbosity level, const format & f)
+{
+    if (level <= verbosity) {
+        printMsg_(level, f);
+        nest = true;
+        nestingLevel++;
+    }
+}
+
+
+void printMsg_(Verbosity level, const format & f)
 {
     if (level > verbosity) return;
     string spaces;
@@ -222,12 +226,6 @@ void msg(Verbosity level, const format & f)
 }
 
 
-void debug(const format & f)
-{
-    msg(lvlDebug, f);
-}
-
-
 void readFull(int fd, unsigned char * buf, size_t count)
 {
     while (count) {
diff --git a/src/libnix/util.hh b/src/libnix/util.hh
index 02a9b7fcb885..e6b600eff8ce 100644
--- a/src/libnix/util.hh
+++ b/src/libnix/util.hh
@@ -101,12 +101,27 @@ class Nest
 private:
     bool nest;
 public:
-    Nest(Verbosity level, const format & f);
+    Nest();
     ~Nest();
+    void open(Verbosity level, const format & f);
 };
 
-void msg(Verbosity level, const format & f);
-void debug(const format & f); /* short-hand for msg(lvlDebug, ...) */
+void printMsg_(Verbosity level, const format & f);
+
+#define startNest(varName, level, f) \
+    Nest varName; \
+    if (level <= verbosity) { \
+      varName.open(level, (f)); \
+    }
+
+#define printMsg(level, f) \
+    do { \
+        if (level <= verbosity) { \
+            printMsg_(level, (f)); \
+        } \
+    } while (0)
+
+#define debug(f) printMsg(lvlDebug, f)
 
 
 /* Wrappers arount read()/write() that read/write exactly the