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,11 +34,14 @@ /// New pass managers should specialize with \p StringRef. template class PassTimingInfo { public: - using PassInstanceID = void *; + /// Value of this type should be capable of uniquely identifying pass invocations + /// and pass instances. + using UniqPassID = std::pair; private: - StringMap PassIDCountMap; ///< Map that counts instances of passes - DenseMap TimingData; ///< timers for pass instances + DenseMap TimingData; ///< timers for pass invocations/instances + StringMap PassIDCountMap;///< Map that counts instances of passes + TimerGroup TG; public: @@ -56,23 +61,81 @@ /// Prints out timing information and then resets the timers. void print(); - /// Returns the timer for the specified pass if it exists. - Timer *getPassTimer(PassInfoT, PassInstanceID); + /// Dumps information for running/triggered timers, useful for debugging + void dump() const; + + /// Returns the timer for the specified pass if it exists, otherwise creates + /// and returns a new timer. + Timer *getPassTimer(PassInfoT); static PassTimingInfo *TheTimeInfo; private: - Timer *newPassTimer(StringRef PassID, StringRef PassDesc); + std::string getTimerDescription(UniqPassID P, StringRef Name, StringRef Desc) { + return Desc; + } + + Timer *newPassTimer(UniqPassID P, StringRef Name, StringRef Desc) { + Timer* T = new Timer(Name, getTimerDescription(P, Name, Desc), TG); + TimingData[P] = T; + return T; + } + + unsigned nextPassID(StringRef PassID) { + return ++PassIDCountMap[PassID]; + } + + void reset() { + TimingData.clear(); + PassIDCountMap.clear(); + } + }; +template <> +std::string PassTimingInfo::getTimerDescription(UniqPassID P, + StringRef ID, StringRef Desc); +template <> +std::string PassTimingInfo::getTimerDescription(UniqPassID P, + StringRef ID, + StringRef Desc); + 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; +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(StringRef PassID, Any IR); + void runAfterPass(StringRef PassID, Any IR); + void startPassManager(StringRef PassID, Any IR); + void finishPassManager(StringRef PassID, Any IR); + +private: + Timer *pushTimer(StringRef PassID); + Timer *popTimer(StringRef PassID); + Timer *startTimer(StringRef PassID); + Timer *stopTimer(StringRef PassID); + + static bool matchPassManager(StringRef PassID); + + SmallVector TimerStack; +}; + } // 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 { //===----------------------------------------------------------------------===// @@ -71,52 +73,72 @@ /// Prints out timing information and then resets the timers. template void PassTimingInfo::print() { TG.print(*CreateInfoOutputFile()); + reset(); } -template -Timer *PassTimingInfo::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); +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().first + << "(" << I.getFirst().second << ")\n"; + } + dbgs() << "\tTriggered:\n"; + for (auto &I : TimingData) { + Timer *MyTimer = I.getSecond(); + if (MyTimer->hasTriggered() && !MyTimer->isRunning()) + dbgs() << "\tTimer " << MyTimer << " for pass " << I.getFirst().first + << "(" << I.getFirst().second << ")\n"; + } } -/// 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::getPassTimer(StringRef PassID, - PassInstanceID Pass) { - init(); - sys::SmartScopedLock Lock(*TimingInfoMutex); - Timer *&T = TimingData[Pass]; - if (!T) - T = newPassTimer(PassID, PassID); - return T; +std::string PassTimingInfo::getTimerDescription(UniqPassID P, + StringRef ID, + StringRef Desc) { + // Bump the count for the instance. + unsigned Count = nextPassID(ID); + // Appending description with a pass-instance number for all but the first one + return Count <= 1 ? Desc.str() : formatv("{0} #{1}", Desc, Count).str(); } template <> -Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) { +std::string PassTimingInfo::getTimerDescription(UniqPassID P, + StringRef ID, + StringRef Desc) { + // Unconditionally appending description with a pass-invocation number. + unsigned Count = P.second; + return formatv("{0} #{1}", Desc, Count).str(); +} + +/// Returns the timer for the specified pass instance \p Pass. +/// Instances of the same pass type (uniquely identified by \p P) are +/// numbered by the order of appearance. +template <> Timer *PassTimingInfo::getPassTimer(Pass *P) { if (P->getAsPMDataManager()) return nullptr; - init(); - sys::SmartScopedLock Lock(*TimingInfoMutex); - Timer *&T = TimingData[Pass]; - + Timer *T = TimingData.lookup({P, 0}); if (!T) { StringRef PassName = P->getPassName(); StringRef PassArgument; if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID())) PassArgument = PI->getPassArgument(); - T = newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName); + T = newPassTimer({P, 0}, PassArgument.empty() ? PassName : PassArgument, PassName); } return T; } +/// Returns the timer for the specified pass invocation of \p PassID. +/// Each time it creates a new timer. +template <> Timer *PassTimingInfo::getPassTimer(StringRef PassID) { + // Bump counts for each request of the timer. + unsigned Count = nextPassID(PassID); + UniqPassID UID{PassID, Count}; + return newPassTimer(UID, PassID, PassID); +} + template PassTimingInfo *PassTimingInfo::TheTimeInfo; @@ -125,16 +147,19 @@ Timer *getPassTimer(Pass *P) { PassTimingInfo::init(); - if (PassTimingInfo::TheTimeInfo) - return PassTimingInfo::TheTimeInfo->getPassTimer(P, P); + if (PassTimingInfo::TheTimeInfo) { + sys::SmartScopedLock Lock(*TimingInfoMutex); + return PassTimingInfo::TheTimeInfo->getPassTimer(P); + } return nullptr; } -Timer *getPassTimer(StringRef PassName) { +Timer *getPassTimer(StringRef PassID) { PassTimingInfo::init(); - if (PassTimingInfo::TheTimeInfo) - return PassTimingInfo::TheTimeInfo->getPassTimer(PassName, - nullptr); + if (PassTimingInfo::TheTimeInfo) { + sys::SmartScopedLock Lock(*TimingInfoMutex); + return PassTimingInfo::TheTimeInfo->getPassTimer(PassID); + } return nullptr; } @@ -147,4 +172,74 @@ PassTimingInfo::TheTimeInfo->print(); } +Timer *TimePassesCallbacks::pushTimer(StringRef PassID) { + Timer* T = getPassTimer(PassID); + TimerStack.push_back(T); + return T; +} + +Timer *TimePassesCallbacks::popTimer(StringRef PassID) { + assert(TimerStack.size() > 0 && "empty stack in popTimer"); + return TimerStack.pop_back_val(); +} + +Timer *TimePassesCallbacks::startTimer(StringRef PassID) { + Timer *MyTimer = pushTimer(PassID); + if (MyTimer && !MyTimer->isRunning()) + MyTimer->startTimer(); + return MyTimer; +} + +Timer *TimePassesCallbacks::stopTimer(StringRef PassID) { + Timer *MyTimer = popTimer(PassID); + if (MyTimer && MyTimer->isRunning()) + MyTimer->stopTimer(); + return MyTimer; +} + +bool TimePassesCallbacks::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 TimePassesCallbacks::runBeforePass(StringRef PassID, Any IR) { + if (matchPassManager(PassID)) + return true; + + // Starting the timer for the pass. + Timer *MyTimer = startTimer(PassID); + assert(MyTimer && "timer should be present"); + LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); + + // we are not going to skip this pass, thus return true. + return true; +} + +void TimePassesCallbacks::runAfterPass(StringRef PassID, Any IR) { + if (matchPassManager(PassID)) + return; + + // Stop the timer for the pass. + Timer *MyTimer = stopTimer(PassID); + assert(MyTimer && "timer should be present"); + + LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); +} + +void TimePassesCallbacks::startPassManager(StringRef PassID, Any IR) { + LLVM_DEBUG(dbgs() << "after startPassManager(" << PassID << ")\n"); + LLVM_DEBUG(PassTimingInfo::TheTimeInfo->dump()); +} + +void TimePassesCallbacks::finishPassManager(StringRef PassID, Any IR) { + LLVM_DEBUG(dbgs() << "after finishPassManager(" << PassID << ")\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" @@ -1898,4 +1899,20 @@ PIC->registerBeforePassCallback(PrintIR::printBeforePass); if (llvm::shouldPrintAfterPass()) PIC->registerAfterPassCallback(PrintIR::printAfterPass); + + if (llvm::TimePassesIsEnabled) { + static TimePassesCallbacks TPCallbacks; + PIC->registerBeforePassCallback( + [](StringRef P, Any IR) { return TPCallbacks.runBeforePass(P, IR); }); + PIC->registerAfterPassCallback( + [](StringRef P, Any IR) { TPCallbacks.runAfterPass(P, IR); }); + PIC->registerBeforeAnalysisCallback( + [](StringRef P, Any IR) { TPCallbacks.runBeforePass(P, IR); }); + PIC->registerAfterAnalysisCallback( + [](StringRef P, Any IR) { TPCallbacks.runAfterPass(P, IR); }); + PIC->registerStartPassManagerCallback( + [](StringRef P, Any IR) { TPCallbacks.startPassManager(P, IR); }); + PIC->registerFinishPassManagerCallback( + [](StringRef P, Any IR) { TPCallbacks.finishPassManager(P, IR); }); + } } 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,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() {