Index: include/llvm/IR/PassTimingInfo.h =================================================================== --- include/llvm/IR/PassTimingInfo.h +++ include/llvm/IR/PassTimingInfo.h @@ -17,8 +17,10 @@ #define LLVM_IR_PASSTIMINGINFO_H #include "llvm/ADT/DenseMap.h" +#include "llvm/ADT/SmallPtrSet.h" #include "llvm/ADT/StringMap.h" #include "llvm/ADT/StringRef.h" +#include "llvm/IR/PassInstrumentation.h" #include "llvm/Support/Timer.h" #include @@ -32,13 +34,16 @@ /// New pass managers should specialize with \p StringRef. template class PassTimingInfo { public: - using PassInstanceID = void *; + /// Address of Pass instance is not always unique + /// (say, new pass manager's PassAdaptor instance has the same address as + /// the pass it governs). + using UniqPassID = std::pair; private: - StringMap PassIDCountMap; ///< Map that counts instances of passes - DenseMap TimingData; ///< timers for pass instances + DenseMap TimingData; ///< timers for pass instances TimerGroup TG; + StringMap PassIDCountMap; ///< Map that counts instances of passes public: /// Default constructor for yet-inactive timeinfo. /// Use \p init() to activate it. @@ -56,8 +61,11 @@ /// Prints out timing information and then resets the timers. void print(); + /// Dumps information for running/triggered timers, useful for debugging + void dump() const; + /// Returns the timer for the specified pass if it exists. - Timer *getPassTimer(PassInfoT, PassInstanceID); + Timer *getPassTimer(PassInfoT); static PassTimingInfo *TheTimeInfo; @@ -66,13 +74,36 @@ }; Timer *getPassTimer(Pass *); -Timer *getPassTimer(StringRef); +Timer *getPassTimer(PassInstanceID); /// 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; +class TimePassesCallbacks { + SmallPtrSet PMTimers; //< Timers for Pass Managers/Adaptors + DenseMap::UniqPassID, + SmallVector> StoppedTimersMap; //< PM Timers stopped for the pass + +public: + TimePassesCallbacks() = default; + + // We need this to be unique per-compilation, thus no copies. + TimePassesCallbacks(const TimePassesCallbacks&) = delete; + void operator=(const TimePassesCallbacks&) = delete; + + // Implementation of timer callbacks + bool runBeforePass(PassInstanceID PassID, Any IR, PassExecutionLocation); + void runAfterPass(PassInstanceID PassID, Any IR, PassExecutionLocation); + void startPassManager(PassInstanceID PassID, Any IR, PassExecutionLocation); + void finishPassManager(PassInstanceID PassID, Any IR, PassExecutionLocation); + +private: + static Timer* startTimer(PassInstanceID); + static Timer* stopTimer(PassInstanceID); +}; + } // namespace llvm #endif Index: lib/IR/PassTimingInfo.cpp =================================================================== --- lib/IR/PassTimingInfo.cpp +++ lib/IR/PassTimingInfo.cpp @@ -32,6 +32,8 @@ using namespace llvm; +#define DEBUG_TYPE "time-passes" + namespace llvm { //===----------------------------------------------------------------------===// @@ -73,6 +75,21 @@ TG.print(*CreateInfoOutputFile()); } +template void PassTimingInfo::dump() const { + dbgs() << "Dumping timers for " << getTypeName() << ":\n\tRunning:\n"; + for (auto &I : TimingData) { + Timer* MyTimer = I.getSecond(); + if (MyTimer->isRunning()) + dbgs() << "\tTimer " << MyTimer << " for pass " << I.getFirst().second << "(" << I.getFirst().first << ")\n"; + } + dbgs() << "\tTriggered:\n"; + for (auto &I : TimingData) { + Timer* MyTimer = I.getSecond(); + if (MyTimer->hasTriggered() && !MyTimer->isRunning()) + dbgs() << "\tTimer " << MyTimer << " for pass " << I.getFirst().second << "(" << I.getFirst().first << ")\n"; + } +} + template Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) { @@ -88,24 +105,26 @@ /// Instances of the same pass type (uniquely identified by \p PassID) are /// numbered by the order of appearance. template <> -Timer *PassTimingInfo::getPassTimer(StringRef PassID, - PassInstanceID Pass) { +Timer *PassTimingInfo::getPassTimer(PassInstanceID PassID) { init(); sys::SmartScopedLock Lock(*TimingInfoMutex); - Timer *&T = TimingData[Pass]; + + UniqPassID UID(PassID.getName(), PassID.getInstance()); + Timer *&T = TimingData[UID]; if (!T) - T = newPassTimer(PassID, PassID); + T = newPassTimer(PassID.getName(), PassID.getName()); return T; } -template <> -Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) { +template <> Timer *PassTimingInfo::getPassTimer(Pass *P) { if (P->getAsPMDataManager()) return nullptr; init(); sys::SmartScopedLock Lock(*TimingInfoMutex); - Timer *&T = TimingData[Pass]; + + UniqPassID UID(StringRef(), P); + Timer *&T = TimingData[UID]; if (!T) { StringRef PassName = P->getPassName(); @@ -121,30 +140,97 @@ PassTimingInfo *PassTimingInfo::TheTimeInfo; template class PassTimingInfo; -template class PassTimingInfo; +template class PassTimingInfo; Timer *getPassTimer(Pass *P) { PassTimingInfo::init(); if (PassTimingInfo::TheTimeInfo) - return PassTimingInfo::TheTimeInfo->getPassTimer(P, P); + return PassTimingInfo::TheTimeInfo->getPassTimer(P); return nullptr; } -Timer *getPassTimer(StringRef PassName) { - PassTimingInfo::init(); - if (PassTimingInfo::TheTimeInfo) - return PassTimingInfo::TheTimeInfo->getPassTimer(PassName, - nullptr); +Timer *getPassTimer(PassInstanceID Pass) { + PassTimingInfo::init(); + if (PassTimingInfo::TheTimeInfo) + return PassTimingInfo::TheTimeInfo->getPassTimer(Pass); return nullptr; } /// If timing is enabled, report the times collected up to now and then reset /// them. void reportAndResetTimings() { - if (PassTimingInfo::TheTimeInfo) - PassTimingInfo::TheTimeInfo->print(); + if (PassTimingInfo::TheTimeInfo) + PassTimingInfo::TheTimeInfo->print(); if (PassTimingInfo::TheTimeInfo) PassTimingInfo::TheTimeInfo->print(); } +Timer* TimePassesCallbacks::startTimer(PassInstanceID PassID) { + Timer* MyTimer = getPassTimer(PassID); + if (MyTimer && !MyTimer->isRunning()) + MyTimer->startTimer(); + return MyTimer; +} + +Timer* TimePassesCallbacks::stopTimer(PassInstanceID PassID) { + Timer* MyTimer = getPassTimer(PassID); + if (MyTimer && MyTimer->isRunning()) + MyTimer->stopTimer(); + return MyTimer; +} + +bool TimePassesCallbacks::runBeforePass(PassInstanceID PassID, Any IR, PassExecutionLocation PLoc) { + // Starting the timer for the pass. + Timer* MyTimer = startTimer(PassID); + assert(MyTimer && "timer should be present"); + // Find running PM timers, stop them and add to the map. + for (Timer *T : PMTimers) { + if (T != MyTimer && T->isRunning()) { + T->stopTimer(); + PassTimingInfo::UniqPassID UID(PassID.getName(), PassID.getInstance()); + StoppedTimersMap[UID].push_back(T); + } + } + LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID.getName() << " " << PassID.getInstance() << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); + + // we are not going to skip this pass, thus return true. + return true; +} + +void TimePassesCallbacks::runAfterPass(PassInstanceID PassID, Any IR, PassExecutionLocation PLoc) { + // Stop the timer for the pass. + Timer* MyTimer = stopTimer(PassID); + assert(MyTimer && "timer should be present"); + + // Find PM timers that we stoppeed for this pass and restart them. + PassTimingInfo::UniqPassID UID(PassID.getName(), PassID.getInstance()); + auto It = StoppedTimersMap.find(UID); + if (It != StoppedTimersMap.end()) { + auto& StoppedTimers = It->getSecond(); + for (Timer* T: StoppedTimers) { + assert(T != MyTimer); + if (T && !T->isRunning()) + T->startTimer(); + } + StoppedTimers.clear(); + } + LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID.getName() << " " << PassID.getInstance() << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); +} + +void TimePassesCallbacks::startPassManager(PassInstanceID PassID, Any IR, PassExecutionLocation) { + Timer* MyTimer = startTimer(PassID); + PMTimers.insert(MyTimer); + LLVM_DEBUG(dbgs() << "after startPassManager(" << PassID.getName() << " " << PassID.getInstance() << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); +} + +void TimePassesCallbacks::finishPassManager(PassInstanceID PassID, Any IR, PassExecutionLocation) { + Timer* MyTimer = stopTimer(PassID); + assert(PMTimers.count(MyTimer) && "should be already registered in PM set"); + LLVM_DEBUG(dbgs() << "after finishPassManager(" << PassID.getName() << " " << PassID.getInstance() << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); +} + } // namespace llvm Index: lib/Passes/PassBuilder.cpp =================================================================== --- lib/Passes/PassBuilder.cpp +++ lib/Passes/PassBuilder.cpp @@ -57,6 +57,7 @@ #include "llvm/IR/Dominators.h" #include "llvm/IR/IRPrintingPasses.h" #include "llvm/IR/PassManager.h" +#include "llvm/IR/PassTimingInfo.h" #include "llvm/IR/Verifier.h" #include "llvm/Support/Debug.h" #include "llvm/Support/Regex.h" @@ -1922,4 +1923,16 @@ registerPassInstrumentation([](PassInstrumentation &PI) { PI.registerAfterPassCallback(PrintIR::printAfterPass); }); + if (llvm::TimePassesIsEnabled) { + static TimePassesCallbacks TPCallbacks; + registerPassInstrumentation([](PassInstrumentation &PI) { + using namespace std::placeholders; + PI.registerBeforePassCallback(std::bind(&llvm::TimePassesCallbacks::runBeforePass, &TPCallbacks, _1, _2, _3)); + PI.registerAfterPassCallback(std::bind(&llvm::TimePassesCallbacks::runAfterPass, &TPCallbacks, _1, _2, _3)); + PI.registerBeforeAnalysisCallback(std::bind(&llvm::TimePassesCallbacks::runBeforePass, &TPCallbacks, _1, _2, _3)); + PI.registerAfterAnalysisCallback(std::bind(&llvm::TimePassesCallbacks::runAfterPass, &TPCallbacks, _1, _2, _3)); + PI.registerStartPassManagerCallback(std::bind(&llvm::TimePassesCallbacks::startPassManager, &TPCallbacks, _1, _2, _3)); + PI.registerFinishPassManagerCallback(std::bind(&llvm::TimePassesCallbacks::finishPassManager, &TPCallbacks, _1, _2, _3)); + }); + } } Index: test/Other/new-pm-lto-defaults.ll =================================================================== --- test/Other/new-pm-lto-defaults.ll +++ test/Other/new-pm-lto-defaults.ll @@ -51,10 +51,10 @@ ; CHECK-O1-NEXT: Running analysis: InnerAnalysisManagerProxy<{{.*}}Function ; CHECK-O-NEXT: Running analysis: LazyCallGraphAnalysis ; CHECK-O-NEXT: Running analysis: FunctionAnalysisManagerCGSCCProxy -; CHECK-O-NEXT: Running analysis: PassInstrumentationAnalysis<{{.*}}LazyCallGraph{{.*}}> +; CHECK-O-NEXT: Running analysis: PassInstrumentationProxy<{{.*}}LazyCallGraph{{.*}}> ; CHECK-O-NEXT: Running analysis: OuterAnalysisManagerProxy<{{.*}}LazyCallGraph{{.*}}> ; CHECK-O-NEXT: Running analysis: AAManager -; CHECK-O1-NEXT: Running analysis: PassInstrumentationAnalysis<{{.*}}Function> +; CHECK-O1-NEXT: Running analysis: PassInstrumentationProxy<{{.*}}Function> ; CHECK-O1-NEXT: Running analysis: TargetLibraryAnalysis ; CHECK-O-NEXT: Running pass: ReversePostOrderFunctionAttrsPass ; CHECK-O-NEXT: Running analysis: CallGraphAnalysis Index: test/Other/new-pm-thinlto-defaults.ll =================================================================== --- test/Other/new-pm-thinlto-defaults.ll +++ test/Other/new-pm-thinlto-defaults.ll @@ -59,7 +59,7 @@ ; CHECK-POSTLINK-O-NEXT: Running analysis: ProfileSummaryAnalysis ; CHECK-POSTLINK-O-NEXT: Running analysis: InnerAnalysisManagerProxy ; CHECK-POSTLINK-O-NEXT: Running analysis: OptimizationRemarkEmitterAnalysis -; CHECK-POSTLINK-O-NEXT: Running analysis: PassInstrumentationAnalysis<{{.*}}Function> +; CHECK-POSTLINK-O-NEXT: Running analysis: PassInstrumentationProxy<{{.*}}Function> ; CHECK-O-NEXT: Running pass: PassManager<{{.*}}Module{{.*}}> ; CHECK-O-NEXT: Starting llvm::Module pass manager run. ; CHECK-O-NEXT: Running pass: InferFunctionAttrsPass Index: test/Other/time-passes.ll =================================================================== --- test/Other/time-passes.ll +++ test/Other/time-passes.ll @@ -1,5 +1,7 @@ ; 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 ; ; TIME: Pass execution timing report ; TIME: Total Execution Time: @@ -7,7 +9,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 +18,17 @@ ; TIME-LEGACY-DAG: Dominator Tree Construction ; TIME-LEGACY-DAG: Module Verifier ; TIME-LEGACY-DAG: Target Library Information +; TIME-NEW-DAG: InstCombinePass{{$}} +; TIME-NEW-DAG: InstCombinePass #2 +; TIME-NEW-DAG: LICMPass{{$}} +; TIME-DOUBLE-LICM-NEW-DAG: LICMPass #2 +; 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() {