Subzero: Rewrite the pass timing infrastructure.

src/IceGlobalContext.cpp

Index: src/IceGlobalContext.cpp
diff --git a/src/IceGlobalContext.cpp b/src/IceGlobalContext.cpp
index 319e18a9d6a3c6ecac74d7bc3454b44eed6bbaad..52a943ff3de60b88e87ce6a5a8d4d3412881c52d 100644
--- a/src/IceGlobalContext.cpp
+++ b/src/IceGlobalContext.cpp
@@ -115,6 +115,98 @@ public:
   UndefPool Undefs;
 };
 
+class TimerStack {
+  TimerStack(const TimerStack &) LLVM_DELETED_FUNCTION;
+  TimerStack &operator=(const TimerStack &) LLVM_DELETED_FUNCTION;
+
+public:
+  TimerStack(const IceString &TopLevelName)
+      : FirstTimestamp(timestamp()), LastTimestamp(FirstTimestamp),
+        StateChanges(0) {
+    push(TopLevelName);
+  }
+  void push(const IceString &Name) {
+    update();
+    Stack.push_back(Name);
+    // Construct the new node's recursive name by appending .Name to
+    // the previous top-of-stack's recursive name.
+    IceString Prefix = "";
+    if (!FullNames.empty())
+      Prefix = FullNames.back() + ".";
+    FullNames.push_back(Prefix + Name);

[Karl, 2014/09/29 16:55:07]

Minor nit. There is a lot of string building going on in this method 2 strings
to create Prefix, and one more for the full name).

[Jim Stichnoth, 2014/09/30 17:50:50]

Good point, and it does turn into a real performance problem if you try to add
very fine-grain timing.

I rewrote this as an explicit tree that is built dynamically as new paths are
added.  As such, there may be some extra overhead during the first function
translation, but subsequent functions should be quite fast.

I avoided imposing centralized compile-time marker ID management, using a
pattern of static initialization, while still allowing new marker IDs to be
added dynamically.

+  }
+  void pop(const IceString &Name) {
+    update();
+    assert(!Stack.empty());
+    assert(Stack.back() == Name);
+    (void)Name;
+    Stack.pop_back();
+    FullNames.pop_back();
+  }
+  void dump(Ostream &Str);
+
+private:
+  typedef std::map<IceString, double> MapType;

[Karl, 2014/09/29 16:55:07]

Using string as the key can be quite expensive. Consider using a counter to give
each timer a unique key. Use this key for data updates. It will cut down on the
overhead considerably. Note that tsd::map using a binary tree and will be doing
a lot of expensive compares.

Alternatively, use the pointer value of the timer for the key (if you aren't
worried about ordering).

[Jim Stichnoth, 2014/09/30 17:50:50]

Done, see the comment above.

+  void update();
+  void dumpHelper(Ostream &Str, const MapType &Map, double TotalTime);
+  static double timestamp() {
+    // TODO: Implement in terms of std::chrono for C++11.
+    return llvm::TimeRecord::getCurrentTime(false).getWallTime();
+  }
+  const double FirstTimestamp;
+  volatile double LastTimestamp;
+  std::vector<IceString> Stack;
+  std::vector<IceString> FullNames;
+  MapType RecursiveTime;
+  MapType LeafTime;
+  uint64_t StateChanges;
+};
+
+void TimerStack::update() {
+  ++StateChanges;
+  // Whenever the stack is about to change, we grab the time delta
+  // since the last change and add it to all active recursive elements
+  // and to the non-recursive element for the top of the stack.
+  double Current = timestamp();
+  double Delta = Current - LastTimestamp;
+  LastTimestamp = Current;
+  for (size_t i = 0; i < FullNames.size(); ++i) {
+    RecursiveTime[FullNames[i]] += Delta;
+  }
+  if (!Stack.empty()) {
+    LeafTime[Stack.back()] += Delta;
+  }
+}
+
+void TimerStack::dumpHelper(Ostream &Str, const MapType &Map,
+                            double TotalTime) {
+  // Dump the items in reverse order of their time contribution.
+  typedef std::multimap<double, IceString> RMapType;
+  RMapType MultiMap;
+  for (MapType::const_iterator I = Map.begin(), E = Map.end(); I != E; ++I) {
+    MultiMap.insert(std::make_pair(I->second, I->first));
+  }
+  for (RMapType::const_reverse_iterator I = MultiMap.rbegin(),
+                                        E = MultiMap.rend();
+       I != E; ++I) {
+    char buf[80];
+    snprintf(buf, llvm::array_lengthof(buf), "  %10.6f (%4.1f%%): ", I->first,
+             I->first * 100 / TotalTime);
+    Str << buf << I->second << "\n";
+  }
+}
+
+void TimerStack::dump(Ostream &Str) {
+  update();
+  double TotalTime = LastTimestamp - FirstTimestamp;
+  assert(TotalTime);
+  Str << "Recursive function times:\n";
+  dumpHelper(Str, RecursiveTime, TotalTime);
+  Str << "Non-recursive function times:\n";
+  dumpHelper(Str, LeafTime, TotalTime);
+  Str << "Number of timer updates: " << StateChanges << "\n";
+}
+
 GlobalContext::GlobalContext(llvm::raw_ostream *OsDump,
                              llvm::raw_ostream *OsEmit, VerboseMask Mask,
                              TargetArch Arch, OptLevel Opt,
@@ -122,7 +214,7 @@ GlobalContext::GlobalContext(llvm::raw_ostream *OsDump,
     : StrDump(OsDump), StrEmit(OsEmit), VMask(Mask),
       ConstPool(new ConstantPool()), Arch(Arch), Opt(Opt),
       TestPrefix(TestPrefix), Flags(Flags), HasEmittedFirstMethod(false),
-      RNG("") {}
+      RNG(""), Timers(new TimerStack("main")) {}
 
 // Scan a string for S[0-9A-Z]*_ patterns and replace them with
 // S<num>_ where <num> is the next base-36 value.  If a type name
@@ -384,6 +476,12 @@ ConstantList GlobalContext::getConstantPool(Type Ty) const {
   llvm_unreachable("Unknown type");
 }
 
+void GlobalContext::pushTimer(const IceString &Name) {
+  Timers.get()->push(Name);
+}
+
+void GlobalContext::popTimer(const IceString &Name) { Timers.get()->pop(Name); }
+
 void GlobalContext::dumpStats(const IceString &Name, bool Final) {
   if (Flags.DumpStats) {
     if (Final) {
@@ -395,12 +493,6 @@ void GlobalContext::dumpStats(const IceString &Name, bool Final) {
   }
 }
 
-void Timer::printElapsedUs(GlobalContext *Ctx, const IceString &Tag) const {
-  if (Ctx->isVerbose(IceV_Timing)) {
-    // Prefixing with '#' allows timing strings to be included
-    // without error in textual assembly output.
-    Ctx->getStrDump() << "# " << getElapsedUs() << " usec " << Tag << "\n";
-  }
-}
+void GlobalContext::dumpTimers() { Timers.get()->dump(getStrDump()); }
 
 } // end of namespace Ice