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 a particular 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,24 @@ 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 +108,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 +143,107 @@ 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" @@ -1918,4 +1919,24 @@ 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/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() {