From 15801c88fad38253b19ac2ea77e7597deab5fd6b Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Sun, 9 Nov 2003 10:35:45 +0000 Subject: [PATCH] * 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. :-) --- src/fix-ng/eval.cc | 6 +++--- src/fix-ng/fix.cc | 2 +- src/fix-ng/primops.cc | 10 +++++----- src/fix/fix.cc | 11 ++++++----- src/libmain/shared.cc | 6 +++--- src/libnix/db.cc | 3 ++- src/libnix/exec.cc | 2 +- src/libnix/normalise.cc | 14 +++++++------- src/libnix/util.cc | 30 ++++++++++++++---------------- src/libnix/util.hh | 21 ++++++++++++++++++--- 10 files changed, 60 insertions(+), 45 deletions(-) diff --git a/src/fix-ng/eval.cc b/src/fix-ng/eval.cc index 8e10caa84..2b45b4798 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()", &name)) subs.set(name, undefined); else if (ATmatch(t, "DefFormal(, )", &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 c24ca4d9c..dc2790a60 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 fb923ed46..07281e89b 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()", outPath.c_str())); diff --git a/src/fix/fix.cc b/src/fix/fix.cc index 9a8ff1513..d75e26b00 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()", 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()", 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 39439f8e1..b06f5eb8b 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 c498fab74..63ec2724f 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 00d9e6a0a..47a385f14 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 d3978ac2c..49f86cc6f 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 016ee991a..299a37f6c 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 02a9b7fcb..e6b600eff 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