From c29e5fbb1306a2da869260153cd38cf25986d662 Mon Sep 17 00:00:00 2001 From: Michael Bishop Date: Sat, 1 Sep 2018 17:11:56 -0300 Subject: [PATCH 1/3] improve the stats when profiling --- src/libexpr/eval.cc | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index f41905787..77d1faced 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -1739,17 +1739,16 @@ void EvalState::printStats() uint64_t bValues = nrValues * sizeof(Value); uint64_t bAttrsets = nrAttrsets * sizeof(Bindings) + nrAttrsInAttrsets * sizeof(Attr); + auto sum = bEnvs + bLists + bValues + bAttrsets; + printMsg(v, format(" time elapsed: %1%") % cpuTime); printMsg(v, format(" size of a value: %1%") % sizeof(Value)); printMsg(v, format(" size of an attr: %1%") % sizeof(Attr)); - printMsg(v, format(" environments allocated count: %1%") % nrEnvs); - printMsg(v, format(" environments allocated bytes: %1%") % bEnvs); - printMsg(v, format(" list elements count: %1%") % nrListElems); - printMsg(v, format(" list elements bytes: %1%") % bLists); + printMsg(v, format(" environments allocated: %1% (%2% bytes, %3%%%)") % nrEnvs % bEnvs % ((bEnvs*100) / sum)); + printMsg(v, format(" list elements: %1% (%2% bytes %3%%%)") % nrListElems % bLists % ((bLists*100)/sum)); printMsg(v, format(" list concatenations: %1%") % nrListConcats); - printMsg(v, format(" values allocated count: %1%") % nrValues); - printMsg(v, format(" values allocated bytes: %1%") % bValues); - printMsg(v, format(" sets allocated: %1% (%2% bytes)") % nrAttrsets % bAttrsets); + printMsg(v, format(" values allocated: %1% (%2% bytes %3%%%)") % nrValues % bValues % ((bValues*100)/sum)); + printMsg(v, format(" sets allocated: %1% (%2% bytes %3%%%)") % nrAttrsets % bAttrsets % ((bAttrsets*100)/sum)); printMsg(v, format(" right-biased unions: %1%") % nrOpUpdates); printMsg(v, format(" values copied in right-biased unions: %1%") % nrOpUpdateValuesCopied); printMsg(v, format(" symbols in symbol table: %1%") % symbols.size()); @@ -1761,6 +1760,8 @@ void EvalState::printStats() printMsg(v, format(" number of function calls: %1%") % nrFunctionCalls); printMsg(v, format(" total allocations: %1% bytes") % (bEnvs + bLists + bValues + bAttrsets)); + printMsg(v, format(" sets: %1% (%2% each, %3% mb total), attrs-in-sets: %4% (%5% each, %6% mb total)") % nrAttrsets % sizeof(Bindings) % ((nrAttrsets * sizeof(Bindings)) / 1024 / 1024) % nrAttrsInAttrsets % sizeof(Attr) % ((nrAttrsInAttrsets * sizeof(Attr)) / 1024 / 1024)); + #if HAVE_BOEHMGC GC_word heapSize, totalBytes; GC_get_heap_usage_safe(&heapSize, 0, 0, 0, &totalBytes); From 2fd1008c708be68b56d39be2e1230f29b2ac5ab1 Mon Sep 17 00:00:00 2001 From: Michael Bishop Date: Sat, 1 Sep 2018 19:50:22 -0300 Subject: [PATCH 2/3] add JSON to NIX_SHOW_STATS --- src/libexpr/eval.cc | 114 ++++++++++++++++++++++++++++++++++---------- 1 file changed, 90 insertions(+), 24 deletions(-) diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index 77d1faced..9ad0b1a20 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -6,12 +6,15 @@ #include "globals.hh" #include "eval-inline.hh" #include "download.hh" +#include "json.hh" #include #include #include #include #include +#include +#include #include #include @@ -23,6 +26,7 @@ #endif +using std::cout; namespace nix { @@ -1723,10 +1727,10 @@ bool EvalState::eqValues(Value & v1, Value & v2) } } - void EvalState::printStats() { bool showStats = getEnv("NIX_SHOW_STATS", "0") != "0"; + bool showJsonStats = getEnv("NIX_SHOW_STATS", "0") == "json"; Verbosity v = showStats ? lvlInfo : lvlDebug; printMsg(v, "evaluation statistics:"); @@ -1741,33 +1745,95 @@ void EvalState::printStats() auto sum = bEnvs + bLists + bValues + bAttrsets; - printMsg(v, format(" time elapsed: %1%") % cpuTime); - printMsg(v, format(" size of a value: %1%") % sizeof(Value)); - printMsg(v, format(" size of an attr: %1%") % sizeof(Attr)); - printMsg(v, format(" environments allocated: %1% (%2% bytes, %3%%%)") % nrEnvs % bEnvs % ((bEnvs*100) / sum)); - printMsg(v, format(" list elements: %1% (%2% bytes %3%%%)") % nrListElems % bLists % ((bLists*100)/sum)); - printMsg(v, format(" list concatenations: %1%") % nrListConcats); - printMsg(v, format(" values allocated: %1% (%2% bytes %3%%%)") % nrValues % bValues % ((bValues*100)/sum)); - printMsg(v, format(" sets allocated: %1% (%2% bytes %3%%%)") % nrAttrsets % bAttrsets % ((bAttrsets*100)/sum)); - printMsg(v, format(" right-biased unions: %1%") % nrOpUpdates); - printMsg(v, format(" values copied in right-biased unions: %1%") % nrOpUpdateValuesCopied); - printMsg(v, format(" symbols in symbol table: %1%") % symbols.size()); - printMsg(v, format(" size of symbol table: %1%") % symbols.totalSize()); - 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); - printMsg(v, format(" number of primop calls: %1%") % nrPrimOpCalls); - printMsg(v, format(" number of function calls: %1%") % nrFunctionCalls); - printMsg(v, format(" total allocations: %1% bytes") % (bEnvs + bLists + bValues + bAttrsets)); - - printMsg(v, format(" sets: %1% (%2% each, %3% mb total), attrs-in-sets: %4% (%5% each, %6% mb total)") % nrAttrsets % sizeof(Bindings) % ((nrAttrsets * sizeof(Bindings)) / 1024 / 1024) % nrAttrsInAttrsets % sizeof(Attr) % ((nrAttrsInAttrsets * sizeof(Attr)) / 1024 / 1024)); - #if HAVE_BOEHMGC GC_word heapSize, totalBytes; GC_get_heap_usage_safe(&heapSize, 0, 0, 0, &totalBytes); - printMsg(v, format(" current Boehm heap size: %1% bytes") % heapSize); - printMsg(v, format(" total Boehm heap allocations: %1% bytes") % totalBytes); #endif + if (showJsonStats) { + auto outPath = getEnv("NIX_SHOW_STATS_PATH","-"); + std::fstream fs; + if (outPath != "-") { + fs.open(outPath, std::fstream::out); + printMsg(v, format(" written to: %1%") % outPath); + } + JSONObject topObj(outPath == "-" ? cout : fs, true); + topObj.attr("cpuTime",cpuTime); + { + auto envs = topObj.object("envs"); + envs.attr("number", nrEnvs); + envs.attr("bytes", bEnvs); + } + { + auto lists = topObj.object("list"); + lists.attr("elements", nrListElems); + lists.attr("bytes", bLists); + lists.attr("concats", nrListConcats); + } + { + auto values = topObj.object("values"); + values.attr("number", nrValues); + values.attr("bytes", bValues); + } + { + auto syms = topObj.object("symbols"); + syms.attr("number", symbols.size()); + syms.attr("bytes", symbols.totalSize()); + } + { + auto sets = topObj.object("sets"); + sets.attr("number", nrAttrsets); + sets.attr("bytes", bAttrsets); + } + { + JSONObject sizes = topObj.object("sizes"); + sizes.attr("Env", sizeof(Env)); + sizes.attr("Value", sizeof(Value)); + sizes.attr("Bindings", sizeof(Bindings)); + sizes.attr("Attr", sizeof(Attr)); + } + topObj.attr("nrOpUpdates", nrOpUpdates); + topObj.attr("nrOpUpdateValuesCopied", nrOpUpdateValuesCopied); + topObj.attr("nrThunks", nrThunks); + topObj.attr("nrAvoided", nrAvoided); + topObj.attr("nrLookups", nrLookups); + topObj.attr("nrPrimOpCalls", nrPrimOpCalls); + topObj.attr("nrFunctionCalls", nrFunctionCalls); +#if HAVE_BOEHMGC + JSONObject gc = topObj.object("gc"); + gc.attr("heapSize", heapSize); + gc.attr("totalBytes", totalBytes); +#endif + } else { + if (getEnv("NIX_SHOW_STATS_PATH","-") != "-") { + printError("warning: $NIX_SHOW_STATS_PATH only works in combination with NIX_SHOW_STATS=json"); + } + printMsg(v, format(" time elapsed: %1%") % cpuTime); + printMsg(v, format(" size of a value: %1%") % sizeof(Value)); + printMsg(v, format(" size of an attr: %1%") % sizeof(Attr)); + printMsg(v, format(" environments allocated: %1% (%2% bytes, %3%%%)") % nrEnvs % bEnvs % ((bEnvs*100) / sum)); + printMsg(v, format(" list elements: %1% (%2% bytes %3%%%)") % nrListElems % bLists % ((bLists*100)/sum)); + printMsg(v, format(" list concatenations: %1%") % nrListConcats); + printMsg(v, format(" values allocated: %1% (%2% bytes %3%%%)") % nrValues % bValues % ((bValues*100)/sum)); + printMsg(v, format(" sets allocated: %1% (%2% bytes %3%%%)") % nrAttrsets % bAttrsets % ((bAttrsets*100)/sum)); + printMsg(v, format(" right-biased unions: %1%") % nrOpUpdates); + printMsg(v, format(" values copied in right-biased unions: %1%") % nrOpUpdateValuesCopied); + printMsg(v, format(" symbols in symbol table: %1%") % symbols.size()); + printMsg(v, format(" size of symbol table: %1%") % symbols.totalSize()); + 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); + printMsg(v, format(" number of primop calls: %1%") % nrPrimOpCalls); + printMsg(v, format(" number of function calls: %1%") % nrFunctionCalls); + printMsg(v, format(" total allocations: %1% bytes") % (bEnvs + bLists + bValues + bAttrsets)); + + printMsg(v, format(" sets: %1% (%2% each, %3% mb total), attrs-in-sets: %4% (%5% each, %6% mb total)") % nrAttrsets % sizeof(Bindings) % ((nrAttrsets * sizeof(Bindings)) / 1024 / 1024) % nrAttrsInAttrsets % sizeof(Attr) % ((nrAttrsInAttrsets * sizeof(Attr)) / 1024 / 1024)); + +#if HAVE_BOEHMGC + printMsg(v, format(" current Boehm heap size: %1% bytes") % heapSize); + printMsg(v, format(" total Boehm heap allocations: %1% bytes") % totalBytes); +#endif + } + if (countCalls) { v = lvlInfo; From 4b034f390c207d997465112a814adb60797e1d4d Mon Sep 17 00:00:00 2001 From: Michael Bishop Date: Sun, 2 Sep 2018 18:20:18 -0300 Subject: [PATCH 3/3] remove the old text format output --- src/libexpr/eval.cc | 38 ++++---------------------------------- 1 file changed, 4 insertions(+), 34 deletions(-) diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index 9ad0b1a20..a67b7ae0d 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -1730,9 +1730,7 @@ bool EvalState::eqValues(Value & v1, Value & v2) void EvalState::printStats() { bool showStats = getEnv("NIX_SHOW_STATS", "0") != "0"; - bool showJsonStats = getEnv("NIX_SHOW_STATS", "0") == "json"; Verbosity v = showStats ? lvlInfo : lvlDebug; - printMsg(v, "evaluation statistics:"); struct rusage buf; getrusage(RUSAGE_SELF, &buf); @@ -1743,13 +1741,12 @@ void EvalState::printStats() uint64_t bValues = nrValues * sizeof(Value); uint64_t bAttrsets = nrAttrsets * sizeof(Bindings) + nrAttrsInAttrsets * sizeof(Attr); - auto sum = bEnvs + bLists + bValues + bAttrsets; - #if HAVE_BOEHMGC GC_word heapSize, totalBytes; GC_get_heap_usage_safe(&heapSize, 0, 0, 0, &totalBytes); #endif - if (showJsonStats) { + if (showStats) { + printMsg(v, "evaluation statistics:"); auto outPath = getEnv("NIX_SHOW_STATS_PATH","-"); std::fstream fs; if (outPath != "-") { @@ -1761,6 +1758,7 @@ void EvalState::printStats() { auto envs = topObj.object("envs"); envs.attr("number", nrEnvs); + envs.attr("elements", nrValuesInEnvs); envs.attr("bytes", bEnvs); } { @@ -1783,6 +1781,7 @@ void EvalState::printStats() auto sets = topObj.object("sets"); sets.attr("number", nrAttrsets); sets.attr("bytes", bAttrsets); + sets.attr("elements", nrAttrsInAttrsets); } { JSONObject sizes = topObj.object("sizes"); @@ -1802,35 +1801,6 @@ void EvalState::printStats() JSONObject gc = topObj.object("gc"); gc.attr("heapSize", heapSize); gc.attr("totalBytes", totalBytes); -#endif - } else { - if (getEnv("NIX_SHOW_STATS_PATH","-") != "-") { - printError("warning: $NIX_SHOW_STATS_PATH only works in combination with NIX_SHOW_STATS=json"); - } - printMsg(v, format(" time elapsed: %1%") % cpuTime); - printMsg(v, format(" size of a value: %1%") % sizeof(Value)); - printMsg(v, format(" size of an attr: %1%") % sizeof(Attr)); - printMsg(v, format(" environments allocated: %1% (%2% bytes, %3%%%)") % nrEnvs % bEnvs % ((bEnvs*100) / sum)); - printMsg(v, format(" list elements: %1% (%2% bytes %3%%%)") % nrListElems % bLists % ((bLists*100)/sum)); - printMsg(v, format(" list concatenations: %1%") % nrListConcats); - printMsg(v, format(" values allocated: %1% (%2% bytes %3%%%)") % nrValues % bValues % ((bValues*100)/sum)); - printMsg(v, format(" sets allocated: %1% (%2% bytes %3%%%)") % nrAttrsets % bAttrsets % ((bAttrsets*100)/sum)); - printMsg(v, format(" right-biased unions: %1%") % nrOpUpdates); - printMsg(v, format(" values copied in right-biased unions: %1%") % nrOpUpdateValuesCopied); - printMsg(v, format(" symbols in symbol table: %1%") % symbols.size()); - printMsg(v, format(" size of symbol table: %1%") % symbols.totalSize()); - 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); - printMsg(v, format(" number of primop calls: %1%") % nrPrimOpCalls); - printMsg(v, format(" number of function calls: %1%") % nrFunctionCalls); - printMsg(v, format(" total allocations: %1% bytes") % (bEnvs + bLists + bValues + bAttrsets)); - - printMsg(v, format(" sets: %1% (%2% each, %3% mb total), attrs-in-sets: %4% (%5% each, %6% mb total)") % nrAttrsets % sizeof(Bindings) % ((nrAttrsets * sizeof(Bindings)) / 1024 / 1024) % nrAttrsInAttrsets % sizeof(Attr) % ((nrAttrsInAttrsets * sizeof(Attr)) / 1024 / 1024)); - -#if HAVE_BOEHMGC - printMsg(v, format(" current Boehm heap size: %1% bytes") % heapSize); - printMsg(v, format(" total Boehm heap allocations: %1% bytes") % totalBytes); #endif }