* 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. :-)

5 files changed, 42 insertions, 28 deletions

diff --git a/src/libnix/db.cc b/src/libnix/db.cc
index c498fab748..63ec2724fc 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 00d9e6a0ac..47a385f147 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 d3978ac2c1..49f86cc6fe 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 016ee991a4..299a37f6c8 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 02a9b7fcb8..e6b600eff8 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