Subzero: Improve the -timing output.

src/IceTimerTree.cpp

 //===- subzero/src/IceTimerTree.cpp - Pass timer defs ---------------------===//
 //
 //                        The Subzero Code Generator
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 ///
 /// \file
@@ skipping 210 matching lines @@
     Node.Time = 0;
     Node.UpdateCount = 0;
   }
 }
 
 namespace {
 
 using DumpMapType = std::multimap<double, std::string>;
 
 // Dump the Map items in reverse order of their time contribution.
-void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime) {
+void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime,

[John, 2016/04/08 21:04:31]

TotalTime should be a local...

[Jim Stichnoth, 2016/04/08 21:09:48]

Actually if AddPercents==false, then TotalTime needs to be passed in, but if
AddPercents==true, we need to recompute it from scratch.

+                bool AddPercents) {
   if (!BuildDefs::timers())
     return;
+  if (AddPercents) {
+    // Recompute TotalTime as the sum of the individual times.  This is because
+    // the individual times generally add up to less than 100% because of timer
+    // overhead.
+    TotalTime = 0;
+    for (auto &I : Map) {

[John, 2016/04/08 21:04:32]

const

[Jim Stichnoth, 2016/04/08 21:09:47]

Done.

+      TotalTime += I.first;
+    }
+  }
+  double Sum = 0;
   for (auto &I : reverse_range(Map)) {
-    Str << llvm::format("  %10.6f (%4.1f%%): ", I.first,
-                        I.first * 100 / TotalTime) << I.second << "\n";
+    Sum += I.first;
+    if (AddPercents) {
+      Str << llvm::format("  %10.6f %4.1f%% %5.1f%% ", I.first,
+                          I.first * 100 / TotalTime, Sum * 100 / TotalTime)
+          << I.second << "\n";
+    } else {
+      Str << llvm::format("  %10.6f %4.1f%% ", I.first,
+                          I.first * 100 / TotalTime) << I.second << "\n";
+    }
   }
 }
 
-// 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) {
-  if (!BuildDefs::timers())
-    return;
-  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) {
   if (!BuildDefs::timers())
     return;
   constexpr bool UpdateCounts = true;
   update(UpdateCounts);
   double TotalTime = LastTimestamp - FirstTimestamp;
   assert(TotalTime);
-  char FmtString[30], PrefixStr[30];
+  char PrefixStr[30];
   if (DumpCumulative) {
     Str << Name << " - Cumulative times:\n";

[John, 2016/04/08 21:04:31]

Suggestion: don't end the Str << in the previous line,

  Str << Name << " - Cumulative times:\n"
      << " ... ";

[Jim Stichnoth, 2016/04/08 21:09:47]

Done.

-    size_t MaxInternalCount = 0;
-    for (TimerTreeNode &Node : Nodes)
-      MaxInternalCount = std::max(MaxInternalCount, Node.UpdateCount);
-    makePrintfFormatString(FmtString, llvm::array_lengthof(FmtString),
-                           MaxInternalCount);
-
+    Str << "     Seconds   Pct  EventCnt TimerPath\n";
     DumpMapType CumulativeMap;
     for (TTindex i = 1; i < Nodes.size(); ++i) {
       TTindex Prefix = i;
       std::string Suffix = "";
       while (Prefix) {
         if (Suffix.empty())
           Suffix = IDs[Nodes[Prefix].Interior];
         else
           Suffix = IDs[Nodes[Prefix].Interior] + "." + Suffix;
         assert(Nodes[Prefix].Parent < Prefix);
         Prefix = Nodes[Prefix].Parent;
       }
-      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), FmtString,
+      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9lu ",
                Nodes[i].UpdateCount);
       CumulativeMap.insert(std::make_pair(Nodes[i].Time, PrefixStr + Suffix));
     }
-    dumpHelper(Str, CumulativeMap, TotalTime);
+    constexpr bool NoAddPercents = false;
+    dumpHelper(Str, CumulativeMap, TotalTime, NoAddPercents);
   }
   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);
+  Str << "     Seconds   Pct CumPct  EventCnt TimerName\n";
   DumpMapType FlatMap;
   for (TimerIdT i = 0; i < LeafTimes.size(); ++i) {
     if (LeafCounts[i]) {
-      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), FmtString,
+      snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9lu ",
                LeafCounts[i]);
       FlatMap.insert(std::make_pair(LeafTimes[i], PrefixStr + IDs[i]));
     }
   }
-  dumpHelper(Str, FlatMap, TotalTime);
+  constexpr bool AddPercents = true;
+  dumpHelper(Str, FlatMap, TotalTime, AddPercents);
   Str << "Number of timer updates: " << StateChangeCount << "\n";
 }
 
 double TimerStack::timestamp() {
   // TODO: Implement in terms of std::chrono for C++11.
   return llvm::TimeRecord::getCurrentTime(false).getWallTime();
 }
 
 } // end of namespace Ice