* 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. :-)
This commit is contained in:
Eelco Dolstra 2003-11-09 10:35:45 +00:00
parent d2e3a132fe
commit 15801c88fa
10 changed files with 60 additions and 45 deletions

View file

@ -23,7 +23,6 @@ static Expr substArgs(Expr body, ATermList formals, Expr arg)
while (!ATisEmpty(formals)) { while (!ATisEmpty(formals)) {
ATerm t = ATgetFirst(formals); ATerm t = ATgetFirst(formals);
Expr name, def; Expr name, def;
debug(printTerm(t));
if (ATmatch(t, "NoDefFormal(<term>)", &name)) if (ATmatch(t, "NoDefFormal(<term>)", &name))
subs.set(name, undefined); subs.set(name, undefined);
else if (ATmatch(t, "DefFormal(<term>, <term>)", &name, &def)) 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) 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++; state.nrEvaluated++;
@ -258,7 +258,7 @@ Expr evalExpr(EvalState & state, Expr e)
Expr evalFile(EvalState & state, const Path & path) 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); Expr e = parseExprFromFile(path);
return evalExpr(state, e); return evalExpr(state, e);
} }

View file

@ -60,7 +60,7 @@ static Expr evalExpr2(EvalState & state, Expr e)
static Expr evalStdin(EvalState & state) static Expr evalStdin(EvalState & state)
{ {
Nest nest(lvlTalkative, format("evaluating standard input")); startNest(nest, lvlTalkative, format("evaluating standard input"));
Expr e = ATreadFromFile(stdin); Expr e = ATreadFromFile(stdin);
if (!e) if (!e)
throw Error(format("unable to read a term from stdin")); throw Error(format("unable to read a term from stdin"));

View file

@ -58,7 +58,7 @@ static Path copyAtom(EvalState & state, const Path & srcPath)
Path drvPath = writeTerm(unparseNixExpr(ne), ""); Path drvPath = writeTerm(unparseNixExpr(ne), "");
state.drvHashes[drvPath] = drvHash; state.drvHashes[drvPath] = drvHash;
msg(lvlChatty, format("copied `%1%' -> closure `%2%'") printMsg(lvlChatty, format("copied `%1%' -> closure `%2%'")
% srcPath % drvPath); % srcPath % drvPath);
return drvPath; return drvPath;
} }
@ -107,7 +107,7 @@ static string processBinding(EvalState & state, Expr e, NixExpr & ne)
string s; string s;
bool first = true; bool first = true;
while (!ATisEmpty(es)) { while (!ATisEmpty(es)) {
Nest nest(lvlVomit, format("processing list element")); startNest(nest, lvlVomit, format("processing list element"));
if (!first) s = s + " "; else first = false; if (!first) s = s + " "; else first = false;
s += processBinding(state, evalExpr(state, ATgetFirst(es)), ne); s += processBinding(state, evalExpr(state, ATgetFirst(es)), ne);
es = ATgetNext(es); es = ATgetNext(es);
@ -123,7 +123,7 @@ static string processBinding(EvalState & state, Expr e, NixExpr & ne)
Expr primDerivation(EvalState & state, Expr args) Expr primDerivation(EvalState & state, Expr args)
{ {
Nest nest(lvlVomit, "evaluating derivation"); startNest(nest, lvlVomit, "evaluating derivation");
ATermMap attrs; ATermMap attrs;
args = evalExpr(state, args); args = evalExpr(state, args);
@ -143,7 +143,7 @@ Expr primDerivation(EvalState & state, Expr args)
{ {
string key = aterm2String(ATgetFirst(keys)); string key = aterm2String(ATgetFirst(keys));
Expr value = attrs.get(key); 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 /* The `args' attribute is special: it supplies the
command-line arguments to the builder. */ command-line arguments to the builder. */
@ -199,7 +199,7 @@ Expr primDerivation(EvalState & state, Expr args)
Path drvPath = writeTerm(unparseNixExpr(ne), "-d-" + drvName); Path drvPath = writeTerm(unparseNixExpr(ne), "-d-" + drvName);
state.drvHashes[drvPath] = drvHash; state.drvHashes[drvPath] = drvHash;
msg(lvlChatty, format("instantiated `%1%' -> `%2%'") printMsg(lvlChatty, format("instantiated `%1%' -> `%2%'")
% drvName % drvPath); % drvName % drvPath);
attrs.set("outPath", ATmake("Path(<str>)", outPath.c_str())); attrs.set("outPath", ATmake("Path(<str>)", outPath.c_str()));

View file

@ -273,7 +273,7 @@ static Expr evalExpr2(EvalState & state, Expr e)
Path pkgPath = writeTerm(unparseNixExpr(ne), ""); Path pkgPath = writeTerm(unparseNixExpr(ne), "");
state.pkgHashes[pkgPath] = pkgHash; state.pkgHashes[pkgPath] = pkgHash;
msg(lvlChatty, format("copied `%1%' -> closure `%2%'") printMsg(lvlChatty, format("copied `%1%' -> closure `%2%'")
% srcPath % pkgPath); % srcPath % pkgPath);
return ATmake("NixExpr(<str>)", pkgPath.c_str()); 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); Path pkgPath = writeTerm(unparseNixExpr(ne), "-d-" + name);
state.pkgHashes[pkgPath] = pkgHash; state.pkgHashes[pkgPath] = pkgHash;
msg(lvlChatty, format("instantiated `%1%' -> `%2%'") printMsg(lvlChatty, format("instantiated `%1%' -> `%2%'")
% name % pkgPath); % name % pkgPath);
return ATmake("NixExpr(<str>)", pkgPath.c_str()); 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) 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 /* Consult the memo table to quickly get the normal form of
previously evaluated expressions. */ previously evaluated expressions. */
@ -405,7 +406,7 @@ static Expr evalExpr(EvalState & state, Expr e)
static Expr evalFile(EvalState & state, const Path & relPath) static Expr evalFile(EvalState & state, const Path & relPath)
{ {
Path path = searchPath(state.searchDirs, 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()); Expr e = ATreadFromNamedFile(path.c_str());
if (!e) if (!e)
throw Error(format("unable to read a term from `%1%'") % path); 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) static Expr evalStdin(EvalState & state)
{ {
Nest nest(lvlTalkative, format("evaluating standard input")); startNest(nest, lvlTalkative, format("evaluating standard input"));
Expr e = ATreadFromFile(stdin); Expr e = ATreadFromFile(stdin);
if (!e) if (!e)
throw Error(format("unable to read a term from stdin")); throw Error(format("unable to read a term from stdin"));

View file

@ -64,17 +64,17 @@ int main(int argc, char * * argv)
try { try {
initAndRun(argc, argv); initAndRun(argc, argv);
} catch (UsageError & e) { } catch (UsageError & e) {
msg(lvlError, printMsg(lvlError,
format( format(
"error: %1%\n" "error: %1%\n"
"Try `%2% --help' for more information.") "Try `%2% --help' for more information.")
% e.what() % programId); % e.what() % programId);
return 1; return 1;
} catch (Error & e) { } catch (Error & e) {
msg(lvlError, format("error: %1%") % e.msg()); printMsg(lvlError, format("error: %1%") % e.msg());
return 1; return 1;
} catch (exception & e) { } catch (exception & e) {
msg(lvlError, format("error: %1%") % e.what()); printMsg(lvlError, format("error: %1%") % e.what());
return 1; return 1;
} }

View file

@ -202,7 +202,8 @@ void Database::open(const string & path)
setAccessorCount(fdAccessors, 1); setAccessorCount(fdAccessors, 1);
if (n != 0) { 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. */ /* Open the environment after running recovery. */
openEnv(env, path, DB_RECOVER); openEnv(env, path, DB_RECOVER);

View file

@ -110,7 +110,7 @@ void runProgram(const string & program,
if (!WIFEXITED(status) || WEXITSTATUS(status) != 0) { if (!WIFEXITED(status) || WEXITSTATUS(status) != 0) {
if (keepFailed) { if (keepFailed) {
msg(lvlTalkative, printMsg(lvlTalkative,
format("program `%1%' failed; keeping build directory `%2%'") format("program `%1%' failed; keeping build directory `%2%'")
% program % tmpDir); % program % tmpDir);
delTmpDir.cancel(); delTmpDir.cancel();

View file

@ -20,7 +20,7 @@ static Path useSuccessor(const Path & path)
Path normaliseNixExpr(const Path & _nePath, PathSet pending) Path normaliseNixExpr(const Path & _nePath, PathSet pending)
{ {
Nest nest(lvlTalkative, startNest(nest, lvlTalkative,
format("normalising expression in `%1%'") % (string) _nePath); format("normalising expression in `%1%'") % (string) _nePath);
/* Try to substitute the expression by any known successors in /* Try to substitute the expression by any known successors in
@ -156,13 +156,13 @@ Path normaliseNixExpr(const Path & _nePath, PathSet pending)
} }
/* Run the builder. */ /* Run the builder. */
msg(lvlChatty, format("building...")); printMsg(lvlChatty, format("building..."));
runProgram(ne.derivation.builder, ne.derivation.args, env, runProgram(ne.derivation.builder, ne.derivation.args, env,
nixLogDir + "/" + baseNameOf(nePath)); nixLogDir + "/" + baseNameOf(nePath));
msg(lvlChatty, format("build completed")); printMsg(lvlChatty, format("build completed"));
} else } else
msg(lvlChatty, format("fast build succesful")); printMsg(lvlChatty, format("fast build succesful"));
/* Check whether the output paths were created, and grep each /* Check whether the output paths were created, and grep each
output path to determine what other paths it references. Also make all 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 /* Write the normal form. This does not have to occur in the
transaction below because writing terms is idem-potent. */ transaction below because writing terms is idem-potent. */
ATerm nfTerm = unparseNixExpr(nf); 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"); Path nfPath = writeTerm(nfTerm, "-s");
/* Register each outpat path, and register the normal form. This /* 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) 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); NixExpr ne = exprFromPath(nePath, pending);
if (ne.type != NixExpr::neClosure) if (ne.type != NixExpr::neClosure)
@ -290,7 +290,7 @@ void ensurePath(const Path & path, PathSet pending)
if (isValidPath(path)) return; if (isValidPath(path)) return;
throw Error(format("substitute failed to produce expected output path")); throw Error(format("substitute failed to produce expected output path"));
} catch (Error & e) { } catch (Error & e) {
msg(lvlTalkative, printMsg(lvlTalkative,
format("building of substitute `%1%' for `%2%' failed: %3%") format("building of substitute `%1%' for `%2%' failed: %3%")
% *i % path % e.what()); % *i % path % e.what());
} }

View file

@ -110,7 +110,7 @@ bool pathExists(const Path & path)
void deletePath(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; struct stat st;
if (lstat(path.c_str(), &st)) if (lstat(path.c_str(), &st))
@ -194,15 +194,9 @@ Verbosity verbosity = lvlError;
static int nestingLevel = 0; static int nestingLevel = 0;
Nest::Nest(Verbosity level, const format & f) Nest::Nest()
{ {
if (level > verbosity) nest = false;
nest = false;
else {
msg(level, f);
nest = true;
nestingLevel++;
}
} }
@ -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; if (level > verbosity) return;
string spaces; 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) void readFull(int fd, unsigned char * buf, size_t count)
{ {
while (count) { while (count) {

View file

@ -101,12 +101,27 @@ class Nest
private: private:
bool nest; bool nest;
public: public:
Nest(Verbosity level, const format & f); Nest();
~Nest(); ~Nest();
void open(Verbosity level, const format & f);
}; };
void msg(Verbosity level, const format & f); void printMsg_(Verbosity level, const format & f);
void debug(const format & f); /* short-hand for msg(lvlDebug, ...) */
#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 /* Wrappers arount read()/write() that read/write exactly the