[New PM][PassTiming] implement -time-passes for the new pass manager

Enable time-passes functionality through PassInstrumentation callbacks
for passes and analyses.

TimePassesHandler class keeps all the callbacks, the timing data as it
is being collected as well as the stack of currently active timers.

Parts of the fix that might be somewhat unobvious:
  - mapping of passes into Timer (TimingData) can not be done per-instance.
    PassID name provided into the callback is common for all the pass invocations.
    Thus the only way to get a timing with reasonable granularity is to collect
    timing data per pass invocation, getting a new timer for each BeforePass.
    Hence the key for TimingData uses a pair of <StringRef/unsigned count> to
    uniquely identify a pass invocation.

  - consequently, this new-pass-manager implementation performs no aggregation
    of timing data, reporting timings for each pass invocation separately.
    In that it differs from legacy-pass-manager time-passes implementation that
    reports timing data aggregated per pass instance.

  - pass managers and adaptors are not tracked, similar to how pass managers are
    not tracked in legacy time-passes.

  - TimerStack tracks timers that are active, each BeforePass pushes the new timer
    on stack, each AfterPass pops active timer from stack and stops it.

Reviewers: chandlerc, philip.pfaffe
Differential Revision: https://reviews.llvm.org/D51276

git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@343898 91177308-0d34-0410-b5e6-96231b3b80d8

include/llvm/IR/PassTimingInfo.h

@@ -9,17 +9,24 @@
 /// \file
 ///
 /// This header defines classes/functions to handle pass execution timing
-/// information with an interface suitable for both pass managers.
+/// information with interfaces for both pass managers.
 ///
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_IR_PASSTIMINGINFO_H
 #define LLVM_IR_PASSTIMINGINFO_H
 
+#include "llvm/ADT/Any.h"
+#include "llvm/ADT/DenseMap.h"
+#include "llvm/ADT/StringMap.h"
+#include "llvm/ADT/StringRef.h"
+#include "llvm/Support/Timer.h"
+#include "llvm/Support/TypeName.h"
+#include <memory>
 namespace llvm {
 
 class Pass;
-class Timer;
+class PassInstrumentationCallbacks;
 
 /// If -time-passes has been specified, report the timings immediately and then
 /// reset the timers to zero.
@@ -33,6 +40,68 @@ Timer *getPassTimer(Pass *);
 /// This is the storage for the -time-passes option.
 extern bool TimePassesIsEnabled;
 
+/// This class implements -time-passes functionality for new pass manager.
+/// It provides the pass-instrumentation callbacks that measure the pass
+/// execution time. They collect timing info into individual timers as
+/// 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;
+
+  /// Map of timers for pass invocations
+  DenseMap<PassInvocationID, std::unique_ptr<Timer>> TimingData;
+
+  /// Map that counts invocations of passes, for use in UniqPassID construction.
+  StringMap<unsigned> PassIDCountMap;
+
+  SmallVector<Timer *, 8> TimerStack; //< Stack of currently active timers.
+
+  bool Enabled;
+
+public:
+  TimePassesHandler(bool Enabled = TimePassesIsEnabled);
+
+  /// Destructor handles the print action if it has not been handled before.
+  ~TimePassesHandler() {
+    // First destroying the timers from TimingData, which deploys all their
+    // collected data into the TG time group member, which later prints itself
+    // when being destroyed.
+    TimingData.clear();
+  }
+
+  /// Prints out timing information and then resets the timers.
+  void print();
+
+  // We intend this to be unique per-compilation, thus no copies.
+  TimePassesHandler(const TimePassesHandler &) = delete;
+  void operator=(const TimePassesHandler &) = delete;
+
+  void registerCallbacks(PassInstrumentationCallbacks &PIC);
+
+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);
+
+  /// Returns the incremented counter for the next invocation of \p PassID.
+  unsigned nextPassID(StringRef PassID) { return ++PassIDCountMap[PassID]; }
+
+  void startTimer(StringRef PassID);
+  void stopTimer(StringRef PassID);
+
+  // Implementation of pass instrumentation callbacks.
+  bool runBeforePass(StringRef PassID, Any IR);
+  void runAfterPass(StringRef PassID, Any IR);
+};
+
 } // namespace llvm
 
 #endif

include/llvm/Passes/StandardInstrumentations.h

@@ -17,13 +17,15 @@
 #define LLVM_PASSES_STANDARDINSTRUMENTATIONS_H
 
 #include "llvm/IR/PassInstrumentation.h"
+#include "llvm/IR/PassTimingInfo.h"
 
 namespace llvm {
 
 /// This class provides an interface to register all the standard pass
 /// instrumentations and manages their state (if any).
 class StandardInstrumentations {
-  // for now we do not have instrumentations with state
+  TimePassesHandler TimePasses;
+
 public:
   StandardInstrumentations() = default;
 

lib/IR/PassTimingInfo.cpp

@@ -20,6 +20,7 @@
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringRef.h"
+#include "llvm/IR/PassInstrumentation.h"
 #include "llvm/Pass.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Debug.h"
@@ -33,6 +34,8 @@
 
 using namespace llvm;
 
+#define DEBUG_TYPE "time-passes"
+
 namespace llvm {
 
 bool TimePassesIsEnabled = false;
@@ -45,7 +48,7 @@ namespace {
 namespace legacy {
 
 //===----------------------------------------------------------------------===//
-// TimingInfo implementation
+// Legacy pass manager's PassTimingInfo implementation
 
 /// Provides an interface for collecting pass timing information.
 ///
@@ -156,4 +159,108 @@ void reportAndResetTimings() {
     legacy::PassTimingInfo::TheTimeInfo->print();
 }
 
+//===----------------------------------------------------------------------===//
+// 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) {
+  // Bump counts for each request of the timer.
+  unsigned Count = nextPassID(PassID);
+
+  // Unconditionally appending description with a pass-invocation number.
+  std::string FullDesc = formatv("{0} #{1}", PassID, Count).str();
+
+  PassInvocationID UID{PassID, Count};
+  Timer *T = new Timer(PassID, FullDesc, TG);
+  auto Pair = TimingData.try_emplace(UID, T);
+  assert(Pair.second && "should always create a new timer");
+  return *(Pair.first->second.get());
+}
+
+TimePassesHandler::TimePassesHandler(bool Enabled)
+    : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled) {}
+
+void TimePassesHandler::print() { TG.print(*CreateInfoOutputFile()); }
+
+LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
+  dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
+         << ":\n\tRunning:\n";
+  for (auto &I : TimingData) {
+    const Timer *MyTimer = I.second.get();
+    if (!MyTimer || MyTimer->isRunning())
+      dbgs() << "\tTimer " << MyTimer << " for pass " << I.first.first << "("
+             << I.first.second << ")\n";
+  }
+  dbgs() << "\tTriggered:\n";
+  for (auto &I : TimingData) {
+    const Timer *MyTimer = I.second.get();
+    if (!MyTimer || (MyTimer->hasTriggered() && !MyTimer->isRunning()))
+      dbgs() << "\tTimer " << MyTimer << " for pass " << I.first.first << "("
+             << I.first.second << ")\n";
+  }
+}
+
+void TimePassesHandler::startTimer(StringRef PassID) {
+  Timer &MyTimer = getPassTimer(PassID);
+  TimerStack.push_back(&MyTimer);
+  if (!MyTimer.isRunning())
+    MyTimer.startTimer();
+}
+
+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();
+}
+
+static bool matchPassManager(StringRef PassID) {
+  size_t prefix_pos = PassID.find('<');
+  if (prefix_pos == StringRef::npos)
+    return false;
+  StringRef Prefix = PassID.substr(0, prefix_pos);
+  return Prefix.endswith("PassManager") || Prefix.endswith("PassAdaptor") ||
+         Prefix.endswith("AnalysisManagerProxy");
+}
+
+bool TimePassesHandler::runBeforePass(StringRef PassID, Any IR) {
+  if (matchPassManager(PassID))
+    return true;
+
+  startTimer(PassID);
+
+  LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n");
+  LLVM_DEBUG(dump());
+
+  // we are not going to skip this pass, thus return true.
+  return true;
+}
+
+void TimePassesHandler::runAfterPass(StringRef PassID, Any IR) {
+  if (matchPassManager(PassID))
+    return;
+
+  stopTimer(PassID);
+
+  LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n");
+  LLVM_DEBUG(dump());
+}
+
+void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
+  if (!Enabled)
+    return;
+
+  PIC.registerBeforePassCallback(
+      [this](StringRef P, Any IR) { return this->runBeforePass(P, IR); });
+  PIC.registerAfterPassCallback(
+      [this](StringRef P, Any IR) { this->runAfterPass(P, IR); });
+  PIC.registerBeforeAnalysisCallback(
+      [this](StringRef P, Any IR) { this->runBeforePass(P, IR); });
+  PIC.registerAfterAnalysisCallback(
+      [this](StringRef P, Any IR) { this->runAfterPass(P, IR); });
+}
+
 } // namespace llvm

lib/Passes/StandardInstrumentations.cpp

@@ -112,4 +112,5 @@ void StandardInstrumentations::registerCallbacks(
     PIC.registerBeforePassCallback(PrintIR::printBeforePass);
   if (llvm::shouldPrintAfterPass())
     PIC.registerAfterPassCallback(PrintIR::printAfterPass);
+  TimePasses.registerCallbacks(PIC);
 }

test/Other/time-passes.ll

@@ -1,5 +1,8 @@
 ; RUN: opt < %s -disable-output -instcombine -instcombine -licm -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY
-; RUN: opt < %s -disable-output -instcombine -instcombine -licm -licm -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY --check-prefix=TIME-DOUBLE-LICM
+; RUN: opt < %s -disable-output -instcombine -instcombine -licm -licm -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY --check-prefix=TIME-DOUBLE-LICM-LEGACY
+; RUN: opt < %s -disable-output -passes='instcombine,instcombine,loop(licm)' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-NEW
+; RUN: opt < %s -disable-output -passes='instcombine,loop(licm),instcombine,loop(licm)' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-NEW -check-prefix=TIME-DOUBLE-LICM-NEW
+; RUN: opt < %s -disable-output -passes='default<O2>' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME
 ;
 ; TIME: Pass execution timing report
 ; TIME: Total Execution Time:
@@ -7,7 +10,7 @@
 ; TIME-LEGACY-DAG:   Combine redundant instructions{{$}}
 ; TIME-LEGACY-DAG:   Combine redundant instructions #2
 ; TIME-LEGACY-DAG:   Loop Invariant Code Motion{{$}}
-; TIME-DOUBLE-LICM-DAG:  Loop Invariant Code Motion #2
+; TIME-DOUBLE-LICM-LEGACY-DAG: Loop Invariant Code Motion #2
 ; TIME-LEGACY-DAG:   Scalar Evolution Analysis
 ; TIME-LEGACY-DAG:   Loop-Closed SSA Form Pass
 ; TIME-LEGACY-DAG:   LCSSA Verifier
@@ -16,6 +19,23 @@
 ; TIME-LEGACY-DAG:   Dominator Tree Construction
 ; TIME-LEGACY-DAG:   Module Verifier
 ; TIME-LEGACY-DAG:   Target Library Information
+; TIME-NEW-DAG:      InstCombinePass #1
+; TIME-NEW-DAG:      InstCombinePass #2
+; TIME-NEW-DAG:      InstCombinePass #3
+; TIME-NEW-DAG:      InstCombinePass #4
+; TIME-NEW-DAG:      LICMPass #1
+; TIME-NEW-DAG:      LICMPass #2
+; TIME-NEW-DAG:      LICMPass #3
+; TIME-DOUBLE-LICM-NEW-DAG:      LICMPass #4
+; TIME-DOUBLE-LICM-NEW-DAG:      LICMPass #5
+; TIME-DOUBLE-LICM-NEW-DAG:      LICMPass #6
+; TIME-NEW-DAG:      LCSSAPass
+; TIME-NEW-DAG:      LoopSimplifyPass
+; TIME-NEW-DAG:      ScalarEvolutionAnalysis
+; TIME-NEW-DAG:      LoopAnalysis
+; TIME-NEW-DAG:      VerifierPass
+; TIME-NEW-DAG:      DominatorTreeAnalysis
+; TIME-NEW-DAG:      TargetLibraryAnalysis
 ; TIME: Total{{$}}
 
 define i32 @foo() {