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

[aeubanks]

Summary

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.

[aeubanks]

actually I realized we can move analyses to a separate TimerGroup

[aeubanks]

support analyses

[aeubanks]

add comment

llvm/include/llvm/IR/PassTimingInfo.h

 /// passes are being run. At the end of its life-time it prints the resulting
 /// timing report.
 class TimePassesHandler {
   /// Value of this type is capable of uniquely identifying pass invocations.
   /// It is a pair of string Pass-Identifier (which for now is common
   /// 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
   /// CreateInfoOutputFile().
   raw_ostream *OutStream = nullptr;
 
   bool Enabled;
   bool PerRun;
public:
   /// Set a custom output stream for subsequent reporting.
   void setOutStream(raw_ostream &OutStream);
 
 private:
   /// Dumps information for running/triggered timers, useful for debugging
   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
 
 #endif

llvm/lib/IR/PassTimingInfo.cpp

public:
   static PassTimingInfo *TheTimeInfo;
 
 private:
   Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
 };
 
 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.
   // Then TG member is (implicitly) deleted, actually printing the report.
   TimingData.clear();
 }
 
 void PassTimingInfo::init() {

 }
 
 //===----------------------------------------------------------------------===//
 // Pass timing handling for the New Pass Manager
 //===----------------------------------------------------------------------===//
 
 /// 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)
       Timers.emplace_back(new Timer(PassID, PassID, TG));
     return *Timers.front();
   }
 
   // Take a vector of Timers created for this \p PassID and append
   // one more timer to it.
   TimerVector &Timers = TimingData[PassID];
   unsigned Count = Timers.size() + 1;
 
   std::string FullDesc = formatv("{0} #{1}", PassID, Count).str();
 
   Timer *T = new Timer(PassID, FullDesc, TG);
   Timers.emplace_back(T);
   assert(Count == Timers.size() && "Timers vector not adjusted correctly.");
 
   return *T;
 }
 
 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) {}
 
 void TimePassesHandler::setOutStream(raw_ostream &Out) {
   OutStream = &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 {
   dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
          << ":\n\tRunning:\n";
   for (auto &I : TimingData) {
     StringRef PassID = I.getKey();
     const TimerVector& MyTimers = I.getValue();
for (auto &I : TimingData) {
     for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
       const Timer* MyTimer = MyTimers[idx].get();
       if (MyTimer && MyTimer->hasTriggered() && !MyTimer->isRunning())
         dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
     }
   }
 }
 
-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;
-
-  startTimer(PassID);
-
-  LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n");
-  LLVM_DEBUG(dump());
+  assert(ActivePassTimer);
+  assert(ActivePassTimer->isRunning());
+  ActivePassTimer->stopTimer();
+  ActivePassTimer = nullptr;
+}
+
+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();
   }
 
-void TimePassesHandler::runAfterPass(StringRef PassID) {
-  if (isSpecialPass(PassID,
-                    {"PassManager", "PassAdaptor", "AnalysisManagerProxy"}))
-    return;
+  Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ false);
+  AnalysisActiveTimerStack.push_back(&MyTimer);
+  if (!MyTimer.isRunning())
+    MyTimer.startTimer();
+}
 
-  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

 ; TIME-PER-RUN-DAG:      InstCombinePass #3
 ; TIME-PER-RUN-DAG:      InstCombinePass #4
 ; TIME-PER-RUN-DAG:      LICMPass #1
 ; TIME-PER-RUN-DAG:      LICMPass #2
 ; TIME-PER-RUN-DAG:      LICMPass #3
 ; 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{{$}}
 
 define i32 @foo() {
   %res = add i32 5, 4
   br label %loop1
 loop1:

llvm/unittests/IR/TimePassesTest.cpp

TEST(TimePassesTest, CustomOut) {
   // Setup time-passes handler and redirect output to the stream.
   std::unique_ptr<TimePassesHandler> TimePasses =
       std::make_unique<TimePassesHandler>(true);
   TimePasses->setOutStream(ReportStream);
   TimePasses->registerCallbacks(PIC);
 
   // 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();
 
   // There should be Pass1 and Pass2 in the report
   EXPECT_FALSE(TimePassesStr.empty());
   EXPECT_TRUE(TimePassesStr.str().contains("report"));
   EXPECT_TRUE(TimePassesStr.str().contains("Pass1"));