[PassTimingInfo] Stop double (or worse) counting passes/analyses

If we nest timers, we end up double counting anything nested.

The most egregious is ModuleInlinerWrapperPass/DevirtSCCRepeatedPass showing up as >20% of the total time when they're just wrappers.

Analyses also end up getting counted multiple times because they're nested inside wrappers and passes.

Ignore ModuleInlinerWrapperPass/DevirtSCCRepeatedPass and put analyses into their own TimerGroup.

Reviewed By: asbirlea

Differential Revision: https://reviews.llvm.org/D135219

Author: aeubanks

llvm/include/llvm/IR/PassTimingInfo.h

@@ -47,15 +47,19 @@ class TimePassesHandler {
   /// to all the instance of a given pass) + sequential invocation counter.
   using PassInvocationID = std::pair<StringRef, unsigned>;
 
-  /// A group of all pass-timing timers.
-  TimerGroup TG;
+  /// Groups of timers for passes and analyses.
+  TimerGroup PassTG;
+  TimerGroup AnalysisTG;
 
   using TimerVector = llvm::SmallVector<std::unique_ptr<Timer>, 4>;
   /// Map of timers for pass invocations
   StringMap<TimerVector> TimingData;
 
-  /// Stack of currently active timers.
-  SmallVector<Timer *, 8> TimerStack;
+  /// Currently active pass timer.
+  Timer *ActivePassTimer = nullptr;
+  /// Stack of currently active analysis timers. Analyses can request other
+  /// analyses.
+  SmallVector<Timer *, 8> AnalysisActiveTimerStack;
 
   /// Custom output stream to print timing information into.
   /// By default (== nullptr) we emit time report into the stream created by
@@ -89,14 +93,12 @@ class TimePassesHandler {
   LLVM_DUMP_METHOD void dump() const;
 
   /// Returns the new timer for each new run of the pass.
-  Timer &getPassTimer(StringRef PassID);
+  Timer &getPassTimer(StringRef PassID, bool IsPass);
 
-  void startTimer(StringRef PassID);
-  void stopTimer(StringRef PassID);
-
-  // Implementation of pass instrumentation callbacks.
-  void runBeforePass(StringRef PassID);
-  void runAfterPass(StringRef PassID);
+  void startAnalysisTimer(StringRef PassID);
+  void stopAnalysisTimer(StringRef PassID);
+  void startPassTimer(StringRef PassID);
+  void stopPassTimer(StringRef PassID);
 };
 
 } // namespace llvm

llvm/lib/IR/PassTimingInfo.cpp

@@ -94,8 +94,7 @@ class PassTimingInfo {
 
 static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
 
-PassTimingInfo::PassTimingInfo()
-    : TG("pass", "... Pass execution timing report ...") {}
+PassTimingInfo::PassTimingInfo() : TG("pass", "Pass execution timing report") {}
 
 PassTimingInfo::~PassTimingInfo() {
   // Deleting the timers accumulates their info into the TG member.
@@ -170,7 +169,8 @@ void reportAndResetTimings(raw_ostream *OutStream) {
 
 /// Returns the timer for the specified pass invocation of \p PassID.
 /// Each time it creates a new timer.
-Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
+Timer &TimePassesHandler::getPassTimer(StringRef PassID, bool IsPass) {
+  TimerGroup &TG = IsPass ? PassTG : AnalysisTG;
   if (!PerRun) {
     TimerVector &Timers = TimingData[PassID];
     if (Timers.size() == 0)
@@ -193,8 +193,9 @@ Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
 }
 
 TimePassesHandler::TimePassesHandler(bool Enabled, bool PerRun)
-    : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled),
-      PerRun(PerRun) {}
+    : PassTG("pass", "Pass execution timing report"),
+      AnalysisTG("analysis", "Analysis execution timing report"),
+      Enabled(Enabled), PerRun(PerRun) {}
 
 TimePassesHandler::TimePassesHandler()
     : TimePassesHandler(TimePassesIsEnabled, TimePassesPerRun) {}
@@ -206,7 +207,16 @@ void TimePassesHandler::setOutStream(raw_ostream &Out) {
 void TimePassesHandler::print() {
   if (!Enabled)
     return;
-  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
+  std::unique_ptr<raw_ostream> MaybeCreated;
+  raw_ostream *OS = OutStream;
+  if (OutStream) {
+    OS = OutStream;
+  } else {
+    MaybeCreated = CreateInfoOutputFile();
+    OS = &*MaybeCreated;
+  }
+  PassTG.print(*OS, true);
+  AnalysisTG.print(*OS, true);
 }
 
 LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
@@ -233,61 +243,77 @@ LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
   }
 }
 
-void TimePassesHandler::startTimer(StringRef PassID) {
-  Timer &MyTimer = getPassTimer(PassID);
-  TimerStack.push_back(&MyTimer);
-  if (!MyTimer.isRunning())
-    MyTimer.startTimer();
+static bool shouldIgnorePass(StringRef PassID) {
+  return isSpecialPass(PassID,
+                       {"PassManager", "PassAdaptor", "AnalysisManagerProxy",
+                        "ModuleInlinerWrapperPass", "DevirtSCCRepeatedPass"});
 }
 
-void TimePassesHandler::stopTimer(StringRef PassID) {
-  assert(TimerStack.size() > 0 && "empty stack in popTimer");
-  Timer *MyTimer = TimerStack.pop_back_val();
-  assert(MyTimer && "timer should be present");
-  if (MyTimer->isRunning())
-    MyTimer->stopTimer();
+void TimePassesHandler::startPassTimer(StringRef PassID) {
+  if (shouldIgnorePass(PassID))
+    return;
+  assert(!ActivePassTimer && "should only have one pass timer at a time");
+  Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ true);
+  ActivePassTimer = &MyTimer;
+  assert(!MyTimer.isRunning());
+  MyTimer.startTimer();
 }
 
-void TimePassesHandler::runBeforePass(StringRef PassID) {
-  if (isSpecialPass(PassID,
-                    {"PassManager", "PassAdaptor", "AnalysisManagerProxy"}))
+void TimePassesHandler::stopPassTimer(StringRef PassID) {
+  if (shouldIgnorePass(PassID))
     return;
+  assert(ActivePassTimer);
+  assert(ActivePassTimer->isRunning());
+  ActivePassTimer->stopTimer();
+  ActivePassTimer = nullptr;
+}
 
-  startTimer(PassID);
+void TimePassesHandler::startAnalysisTimer(StringRef PassID) {
+  // Stop the previous analysis timer to prevent double counting when an
+  // analysis requests another analysis.
+  if (!AnalysisActiveTimerStack.empty()) {
+    assert(AnalysisActiveTimerStack.back()->isRunning());
+    AnalysisActiveTimerStack.back()->stopTimer();
+  }
 
-  LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n");
-  LLVM_DEBUG(dump());
+  Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ false);
+  AnalysisActiveTimerStack.push_back(&MyTimer);
+  if (!MyTimer.isRunning())
+    MyTimer.startTimer();
 }
 
-void TimePassesHandler::runAfterPass(StringRef PassID) {
-  if (isSpecialPass(PassID,
-                    {"PassManager", "PassAdaptor", "AnalysisManagerProxy"}))
-    return;
-
-  stopTimer(PassID);
+void TimePassesHandler::stopAnalysisTimer(StringRef PassID) {
+  assert(!AnalysisActiveTimerStack.empty() && "empty stack in popTimer");
+  Timer *MyTimer = AnalysisActiveTimerStack.pop_back_val();
+  assert(MyTimer && "timer should be present");
+  if (MyTimer->isRunning())
+    MyTimer->stopTimer();
 
-  LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n");
-  LLVM_DEBUG(dump());
+  // Restart the previously stopped timer.
+  if (!AnalysisActiveTimerStack.empty()) {
+    assert(!AnalysisActiveTimerStack.back()->isRunning());
+    AnalysisActiveTimerStack.back()->startTimer();
+  }
 }
 
 void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
   if (!Enabled)
     return;
 
   PIC.registerBeforeNonSkippedPassCallback(
-      [this](StringRef P, Any) { this->runBeforePass(P); });
+      [this](StringRef P, Any) { this->startPassTimer(P); });
   PIC.registerAfterPassCallback(
       [this](StringRef P, Any, const PreservedAnalyses &) {
-        this->runAfterPass(P);
+        this->stopPassTimer(P);
       });
   PIC.registerAfterPassInvalidatedCallback(
       [this](StringRef P, const PreservedAnalyses &) {
-        this->runAfterPass(P);
+        this->stopPassTimer(P);
       });
   PIC.registerBeforeAnalysisCallback(
-      [this](StringRef P, Any) { this->runBeforePass(P); });
+      [this](StringRef P, Any) { this->startAnalysisTimer(P); });
   PIC.registerAfterAnalysisCallback(
-      [this](StringRef P, Any) { this->runAfterPass(P); });
+      [this](StringRef P, Any) { this->stopAnalysisTimer(P); });
 }
 
 } // namespace llvm

llvm/test/Other/time-passes.ll

@@ -27,29 +27,34 @@
 ; TIME-DOUBLE-LICM-DAG:      LICMPass #4
 ; TIME-DOUBLE-LICM-DAG:      LICMPass #5
 ; TIME-DOUBLE-LICM-DAG:      LICMPass #6
-; TIME-PER_RUN-DAG:      LCSSAPass
-; TIME-PER_RUN-DAG:      LoopSimplifyPass
-; TIME-PER_RUN-DAG:      ScalarEvolutionAnalysis
-; TIME-PER_RUN-DAG:      LoopAnalysis
-; TIME-PER_RUN-DAG:      VerifierPass
-; TIME-PER_RUN-DAG:      DominatorTreeAnalysis
-; TIME-PER_RUN-DAG:      TargetLibraryAnalysis
+; TIME-PER-RUN-DAG:      LCSSAPass
+; TIME-PER-RUN-DAG:      LoopSimplifyPass
+; TIME-PER-RUN-DAG:      VerifierPass
 ; TIME-PER-PASS-DAG:   InstCombinePass
 ; TIME-PER-PASS-DAG:   LICMPass
 ; TIME-PER-PASS-DAG:   LCSSAPass
 ; TIME-PER-PASS-DAG:   LoopSimplifyPass
-; TIME-PER-PASS-DAG:   ScalarEvolutionAnalysis
-; TIME-PER-PASS-DAG:   LoopAnalysis
 ; TIME-PER-PASS-DAG:   VerifierPass
-; TIME-PER-PASS-DAG:   DominatorTreeAnalysis
-; TIME-PER-PASS-DAG:   TargetLibraryAnalysis
 ; TIME-PER-PASS-NOT:   InstCombinePass #
 ; TIME-PER-PASS-NOT:   LICMPass #
 ; TIME-PER-PASS-NOT:   LCSSAPass #
 ; TIME-PER-PASS-NOT:   LoopSimplifyPass #
+; TIME-PER-PASS-NOT:   VerifierPass #
+; TIME: Total{{$}}
+
+; TIME: Analysis execution timing report
+; TIME: Total Execution Time:
+; TIME: Name
+; TIME-PER-RUN-DAG:      ScalarEvolutionAnalysis
+; TIME-PER-RUN-DAG:      LoopAnalysis
+; TIME-PER-RUN-DAG:      DominatorTreeAnalysis
+; TIME-PER-RUN-DAG:      TargetLibraryAnalysis
+; TIME-PER-PASS-DAG:   ScalarEvolutionAnalysis
+; TIME-PER-PASS-DAG:   LoopAnalysis
+; TIME-PER-PASS-DAG:   DominatorTreeAnalysis
+; TIME-PER-PASS-DAG:   TargetLibraryAnalysis
 ; TIME-PER-PASS-NOT:   ScalarEvolutionAnalysis #
 ; TIME-PER-PASS-NOT:   LoopAnalysis #
-; TIME-PER-PASS-NOT:   VerifierPass #
 ; TIME-PER-PASS-NOT:   DominatorTreeAnalysis #
 ; TIME-PER-PASS-NOT:   TargetLibraryAnalysis #
 ; TIME: Total{{$}}

llvm/unittests/IR/TimePassesTest.cpp

@@ -135,9 +135,9 @@ TEST(TimePassesTest, CustomOut) {
 
   // Pretending that passes are running to trigger the timers.
   PI.runBeforePass(Pass1, M);
+  PI.runAfterPass(Pass1, M, PreservedAnalyses::all());
   PI.runBeforePass(Pass2, M);
   PI.runAfterPass(Pass2, M, PreservedAnalyses::all());
-  PI.runAfterPass(Pass1, M, PreservedAnalyses::all());
 
   // Generating report.
   TimePasses->print();