[PassTiming] reporting time-passes separately for multiple pass instances of the same pass

Summary:
Refactoring done by rL340872 accidentally appeared to be non-NFC, changing the way how
multiple instances of the same pass are handled - aggregation of results by PassName
forced data for multiple instances to be merged together and reported as one line.

Getting back to creating/reporting timers per pass instance.
Reporting was a bit enhanced by counting pass instances and adding #<num> suffix
to the pass description. Note that it is instances that are being counted,
not invocations of them.

time-passes test updated to account for multiple passes being run.

Reviewers: paquette, jhenderson, MatzeB, skatkov

Reviewed By: skatkov

Subscribers: llvm-commits

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

llvm-svn: 341346

llvm/include/llvm/IR/PassTimingInfo.h

@@ -16,6 +16,7 @@
 #ifndef LLVM_IR_PASSTIMINGINFO_H
 #define LLVM_IR_PASSTIMINGINFO_H
 
+#include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Timer.h"
@@ -30,7 +31,12 @@ class TimerGroup;
 /// Legacy pass managers should specialize with \p PassInfo*.
 /// New pass managers should specialize with \p StringRef.
 template <typename PassInfoT> class PassTimingInfo {
-  StringMap<Timer *> TimingData;
+public:
+  using PassInstanceID = void *;
+
+private:
+  StringMap<unsigned> PassIDCountMap; ///< Map that counts instances of passes
+  DenseMap<PassInstanceID, Timer *> TimingData; ///< timers for pass instances
   TimerGroup TG;
 
 public:
@@ -51,9 +57,12 @@ public:
   void print();
 
   /// Returns the timer for the specified pass if it exists.
-  Timer *getPassTimer(PassInfoT);
+  Timer *getPassTimer(PassInfoT, PassInstanceID);
 
   static PassTimingInfo *TheTimeInfo;
+
+private:
+  Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
 };
 
 Timer *getPassTimer(Pass *);

llvm/lib/IR/PassTimingInfo.cpp

@@ -23,6 +23,7 @@
 #include "llvm/Pass.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Debug.h"
+#include "llvm/Support/FormatVariadic.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Mutex.h"
 #include "llvm/Support/Timer.h"
@@ -53,7 +54,7 @@ template <typename PassT> PassTimingInfo<PassT>::~PassTimingInfo() {
   // Deleting the timers accumulates their info into the TG member.
   // Then TG member is (implicitly) deleted, actually printing the report.
   for (auto &I : TimingData)
-    delete I.getValue();
+    delete I.getSecond();
 }
 
 template <typename PassT> void PassTimingInfo<PassT>::init() {
@@ -61,7 +62,7 @@ template <typename PassT> void PassTimingInfo<PassT>::init() {
     return;
 
   // Constructed the first time this is called, iff -time-passes is enabled.
-  // This guarantees that the object will be constructed before static globals,
+  // This guarantees that the object will be constructed after static globals,
   // thus it will be destroyed before them.
   static ManagedStatic<PassTimingInfo> TTI;
   TheTimeInfo = &*TTI;
@@ -72,30 +73,46 @@ template <typename PassT> void PassTimingInfo<PassT>::print() {
   TG.print(*CreateInfoOutputFile());
 }
 
-/// Return the timer for the specified pass if it exists.
-template <> Timer *PassTimingInfo<StringRef>::getPassTimer(StringRef PassName) {
+template <typename PassInfoT>
+Timer *PassTimingInfo<PassInfoT>::newPassTimer(StringRef PassID,
+                                               StringRef PassDesc) {
+  unsigned &num = PassIDCountMap[PassID];
+  num++;
+  // Appending description with a pass-instance number for all but the first one
+  std::string PassDescNumbered =
+      num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
+  return new Timer(PassID, PassDescNumbered, TG);
+}
+
+/// Returns the timer for the specified pass instance \p Pass.
+/// Instances of the same pass type (uniquely identified by \p PassID) are
+/// numbered by the order of appearance.
+template <>
+Timer *PassTimingInfo<StringRef>::getPassTimer(StringRef PassID,
+                                               PassInstanceID Pass) {
   init();
   sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
-  Timer *&T = TimingData[PassName];
+  Timer *&T = TimingData[Pass];
   if (!T)
-    T = new Timer(PassName, PassName, TG);
+    T = newPassTimer(PassID, PassID);
   return T;
 }
 
-template <> Timer *PassTimingInfo<Pass *>::getPassTimer(Pass *P) {
+template <>
+Timer *PassTimingInfo<Pass *>::getPassTimer(Pass *P, PassInstanceID Pass) {
   if (P->getAsPMDataManager())
     return nullptr;
 
   init();
   sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
-  StringRef PassName = P->getPassName();
-  Timer *&T = TimingData[PassName];
+  Timer *&T = TimingData[Pass];
 
   if (!T) {
+    StringRef PassName = P->getPassName();
     StringRef PassArgument;
     if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID()))
       PassArgument = PI->getPassArgument();
-    T = new Timer(PassArgument.empty() ? PassName : PassArgument, PassName, TG);
+    T = newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName);
   }
   return T;
 }
@@ -109,14 +126,15 @@ template class PassTimingInfo<StringRef>;
 Timer *getPassTimer(Pass *P) {
   PassTimingInfo<Pass *>::init();
   if (PassTimingInfo<Pass *>::TheTimeInfo)
-    return PassTimingInfo<Pass *>::TheTimeInfo->getPassTimer(P);
+    return PassTimingInfo<Pass *>::TheTimeInfo->getPassTimer(P, P);
   return nullptr;
 }
 
 Timer *getPassTimer(StringRef PassName) {
   PassTimingInfo<StringRef>::init();
   if (PassTimingInfo<StringRef>::TheTimeInfo)
-    return PassTimingInfo<StringRef>::TheTimeInfo->getPassTimer(PassName);
+    return PassTimingInfo<StringRef>::TheTimeInfo->getPassTimer(PassName,
+                                                                nullptr);
   return nullptr;
 }
 

llvm/test/Other/time-passes.ll

@@ -1,9 +1,18 @@
-; RUN: opt < %s -disable-output -instcombine -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY
+; 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
 ;
 ; TIME: Pass execution timing report
 ; TIME: Total Execution Time:
 ; TIME: Name
 ; 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-LEGACY-DAG:   Scalar Evolution Analysis
+; TIME-LEGACY-DAG:   Loop-Closed SSA Form Pass
+; TIME-LEGACY-DAG:   LCSSA Verifier
+; TIME-LEGACY-DAG:   Canonicalize natural loops
+; TIME-LEGACY-DAG:   Natural Loop Information
 ; TIME-LEGACY-DAG:   Dominator Tree Construction
 ; TIME-LEGACY-DAG:   Module Verifier
 ; TIME-LEGACY-DAG:   Target Library Information
@@ -11,5 +20,20 @@
 
 define i32 @foo() {
   %res = add i32 5, 4
+  br label %loop1
+loop1:
+  br i1 false, label %loop1, label %end
+end:
   ret i32 %res
 }
+
+define void @bar_with_loops() {
+  br label %loop1
+loop1:
+  br i1 false, label %loop1, label %loop2
+loop2:
+  br i1 true, label %loop2, label %end
+end:
+  ret void
+
+}