Subzero: Rewrite the pass timing infrastructure.

src/IceGlobalContext.cpp

 //===- subzero/src/IceGlobalContext.cpp - Global context defs ---*- C++ -*-===//
 //
 //                        The Subzero Code Generator
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 //
 // This file defines aspects of the compilation that persist across
@@ skipping 97 matching lines @@
 public:
   ConstantPool() {}
   TypePool<float, ConstantFloat, true> Floats;
   TypePool<double, ConstantDouble, true> Doubles;
   TypePool<uint32_t, ConstantInteger32> Integers32;
   TypePool<uint64_t, ConstantInteger64> Integers64;
   TypePool<RelocatableTuple, ConstantRelocatable> Relocatables;
   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,
                              IceString TestPrefix, const ClFlags &Flags)
     : 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
 // legitimately contains that pattern, then the substitution will be
 // made in error and most likely the link will fail.  In this case,
 // the test classes can be rewritten not to use that pattern, which is
 // much simpler and more reliable than implementing a full demangling
 // parser.  Another substitution-in-error may occur if a type
 // identifier ends with the pattern S[0-9A-Z]*, because an immediately
 // following substitution string like "S1_" or "PS1_" may be combined
@@ skipping 241 matching lines @@
     BaseOS << "Unsupported constant type: " << Ty;
     llvm_unreachable(BaseOS.str().c_str());
   } break;
   case IceType_void:
   case IceType_NUM:
     break;
   }
   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) {
       StatsCumulative.dump(Name, getStrDump());
     } else {
       StatsFunction.dump(Name, getStrDump());
       StatsCumulative.dump("_TOTAL_", getStrDump());
     }
   }
 }
 
-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