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

[fedor.sergeev]

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.

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

[skatkov]

Could you please add a test producing something with #2 and #3... I guess any loop pass for function with 2-3 loops should work.

lib/IR/PassTimingInfo.cpp

107–108

Move to if() scope below. It is not used in this scope.

[fedor.sergeev]

In D51535#1221730, @skatkov wrote:

Could you please add a test producing something with #2 and #3... I guess any loop pass for function with 2-3 loops should work.

Nope, 2-3 loops wont add #2/#3.
Numbering is for instances of the pass in the pass pipeline.
Current test will generate #2 for the second instcombine, so I will add it to the pattern.
Will also add a couple loops to make it more evident that multiple "IR units" do not affect the count.

[fedor.sergeev]

as per comments - moving the code around, updating the test.

include/llvm/IR/PassTimingInfo.h

 /// This header defines classes/functions to handle pass execution timing
 /// information with an interface suitable for both pass managers.
 ///
 //===----------------------------------------------------------------------===//
 
 #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"
 #include <string>
 
 namespace llvm {
 
 class Pass;
 class TimerGroup;
 
 /// Provides a generic interface for collecting pass timing information.
 /// 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:
   /// Default constructor for yet-inactive timeinfo.
   /// Use \p init() to activate it.
   PassTimingInfo();
 
   /// Print out timing information and release timers.
   ~PassTimingInfo();
 
   /// Initializes the static \p TheTimeInfo member to a non-null value when
   /// -time-passes is enabled. Leaves it null otherwise.
   ///
   /// This method may be called multiple times.
   static void init();
 
   /// Prints out timing information and then resets the timers.
   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 *);
 Timer *getPassTimer(StringRef);
 
 /// If the user specifies the -time-passes argument on an LLVM tool command line
 /// then the value of this boolean will be true, otherwise false.
 /// This is the storage for the -time-passes option.
 extern bool TimePassesIsEnabled;
 
 } // namespace llvm
 
 #endif

lib/IR/PassTimingInfo.cpp

 
 #include "llvm/IR/PassTimingInfo.h"
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringRef.h"
 #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"
 #include "llvm/Support/raw_ostream.h"
 #include <string>
 
 using namespace llvm;
 

 template <typename PassT>
 PassTimingInfo<PassT>::PassTimingInfo()
     : TG("pass", "... Pass execution timing report ...") {}
 
 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() {
   if (!TimePassesIsEnabled || TheTimeInfo)
     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;
 }
 
 /// Prints out timing information and then resets the timers.
 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;
 }
 
 template <typename PassInfoT>
 PassTimingInfo<PassInfoT> *PassTimingInfo<PassInfoT>::TheTimeInfo;
 
 template class PassTimingInfo<Pass *>;
 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;
 }
 
 /// If timing is enabled, report the times collected up to now and then reset
 /// them.
 void reportAndResetTimings() {
   if (PassTimingInfo<StringRef>::TheTimeInfo)
     PassTimingInfo<StringRef>::TheTimeInfo->print();
   if (PassTimingInfo<Pass *>::TheTimeInfo)
     PassTimingInfo<Pass *>::TheTimeInfo->print();
 }
 
 } // namespace llvm

test/Other/time-passes.ll

-; 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
 ; TIME: Total{{$}}
 
 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
+
+}