Subzero: Enhance the timer dump format.

src/IceTimerTree.cpp

Index: src/IceTimerTree.cpp
diff --git a/src/IceTimerTree.cpp b/src/IceTimerTree.cpp
index cfe3ca5cbaf358a78bf0deea5496c55d72300610..c613ab750cfcd2875899d078024c828986b494c7 100644
--- a/src/IceTimerTree.cpp
+++ b/src/IceTimerTree.cpp
@@ -45,7 +45,8 @@ TimerIdT TimerStack::getTimerID(const IceString &Name) {
 
 // Pushes a new marker onto the timer stack.
 void TimerStack::push(TimerIdT ID) {
-  update();
+  const bool UpdateCounts = false;
+  update(UpdateCounts);
   if (Nodes[StackTop].Children.size() <= ID)
     Nodes[StackTop].Children.resize(ID + 1);
   if (Nodes[StackTop].Children[ID] == 0) {
@@ -61,7 +62,8 @@ void TimerStack::push(TimerIdT ID) {
 // Pop the top marker from the timer stack.  Validates via assert()
 // that the expected marker is popped.
 void TimerStack::pop(TimerIdT ID) {
-  update();
+  const bool UpdateCounts = true;
+  update(UpdateCounts);
   assert(StackTop);
   assert(Nodes[StackTop].Parent < StackTop);
   // Verify that the expected ID is being popped.
@@ -74,7 +76,7 @@ void TimerStack::pop(TimerIdT ID) {
 
 // At a state change (e.g. push or pop), updates the flat and
 // cumulative timings for everything on the timer stack.
-void TimerStack::update() {
+void TimerStack::update(bool UpdateCounts) {
   ++StateChangeCount;
   // Whenever the stack is about to change, we grab the time delta
   // since the last change and add it to all active cumulative
@@ -83,13 +85,20 @@ void TimerStack::update() {
   double Delta = Current - LastTimestamp;
   if (StackTop) {
     TimerIdT Leaf = Nodes[StackTop].Interior;
-    if (Leaf >= LeafTimes.size())
+    if (Leaf >= LeafTimes.size()) {
       LeafTimes.resize(Leaf + 1);
+      LeafCounts.resize(Leaf + 1);
+    }
     LeafTimes[Leaf] += Delta;
+    if (UpdateCounts)
+      ++LeafCounts[Leaf];
   }
   TTindex Prefix = StackTop;
   while (Prefix) {
     Nodes[Prefix].Time += Delta;
+    // Only update a leaf node count, not the internal node counts.
+    if (UpdateCounts && Prefix == StackTop)
+      ++Nodes[Prefix].UpdateCount;
     TTindex Next = Nodes[Prefix].Parent;
     assert(Next < Prefix);
     Prefix = Next;
@@ -105,6 +114,7 @@ void TimerStack::reset() {
   StateChangeCount = 0;
   FirstTimestamp = LastTimestamp = timestamp();
   LeafTimes.assign(LeafTimes.size(), 0);
+  LeafCounts.assign(LeafCounts.size(), 0);
   for (TimerTreeNode &Node : Nodes) {
     Node.Time = 0;

[jvoung (off chromium), 2014/10/14 17:25:50]

Node.UpdateCount = 0 also?

[Jim Stichnoth, 2014/10/14 18:10:09]

Oops, done.

   }
@@ -125,14 +135,36 @@ void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime) {
   }
 }
 
+// Write a printf() format string into Buf[], in the format "[%5lu] ",
+// where "5" is actually the number of digits in MaxVal.  E.g.,
+//   MaxVal=0     ==> "[%1lu] "
+//   MaxVal=5     ==> "[%1lu] "
+//   MaxVal=9876  ==> "[%4lu] "
+void makePrintfFormatString(char *Buf, size_t BufLen, size_t MaxVal) {
+  int NumDigits = 0;
+  do {
+    ++NumDigits;
+    MaxVal /= 10;
+  } while (MaxVal);
+  snprintf(Buf, BufLen, "[%%%dlu] ", NumDigits);
+}
+
 } // end of anonymous namespace
 
 void TimerStack::dump(Ostream &Str, bool DumpCumulative) {
-  update();
+  const bool UpdateCounts = true;
+  update(UpdateCounts);
   double TotalTime = LastTimestamp - FirstTimestamp;
   assert(TotalTime);
+  char FmtString[30], PrefixStr[30];
   if (DumpCumulative) {
     Str << Name << " - Cumulative times:\n";
+    size_t MaxInternalCount = 0;
+    for (TimerTreeNode &Node : Nodes)
+      MaxInternalCount = std::max(MaxInternalCount, Node.UpdateCount);
+    makePrintfFormatString(FmtString, llvm::array_lengthof(FmtString),
+                           MaxInternalCount);
+
     DumpMapType CumulativeMap;
     for (TTindex i = 1; i < Nodes.size(); ++i) {
       TTindex Prefix = i;
@@ -145,14 +177,25 @@ void TimerStack::dump(Ostream &Str, bool DumpCumulative) {
         assert(Nodes[Prefix].Parent < Prefix);
         Prefix = Nodes[Prefix].Parent;
       }
-      CumulativeMap.insert(std::make_pair(Nodes[i].Time, Suffix));
+      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), FmtString,
+               Nodes[i].UpdateCount);
+      CumulativeMap.insert(std::make_pair(Nodes[i].Time, PrefixStr + Suffix));
     }
     dumpHelper(Str, CumulativeMap, TotalTime);
   }
   Str << Name << " - Flat times:\n";
+  size_t MaxLeafCount = 0;
+  for (size_t Count : LeafCounts)
+    MaxLeafCount = std::max(MaxLeafCount, Count);
+  makePrintfFormatString(FmtString, llvm::array_lengthof(FmtString),
+                         MaxLeafCount);
   DumpMapType FlatMap;
   for (TimerIdT i = 0; i < LeafTimes.size(); ++i) {
-    FlatMap.insert(std::make_pair(LeafTimes[i], IDs[i]));
+    if (LeafCounts[i]) {
+      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), FmtString,
+               LeafCounts[i]);
+      FlatMap.insert(std::make_pair(LeafTimes[i], PrefixStr + IDs[i]));
+    }
   }
   dumpHelper(Str, FlatMap, TotalTime);
   Str << "Number of timer updates: " << StateChangeCount << "\n";