diff --git a/llvm/include/llvm/IR/PassTimingInfo.h b/llvm/include/llvm/IR/PassTimingInfo.h index 49a83605c47aa..d464b998fa706 100644 --- a/llvm/include/llvm/IR/PassTimingInfo.h +++ b/llvm/include/llvm/IR/PassTimingInfo.h @@ -47,15 +47,19 @@ class TimePassesHandler { /// to all the instance of a given pass) + sequential invocation counter. using PassInvocationID = std::pair; - /// A group of all pass-timing timers. - TimerGroup TG; + /// Groups of timers for passes and analyses. + TimerGroup PassTG; + TimerGroup AnalysisTG; using TimerVector = llvm::SmallVector, 4>; /// Map of timers for pass invocations StringMap TimingData; - /// Stack of currently active timers. - SmallVector TimerStack; + /// Currently active pass timer. + Timer *ActivePassTimer = nullptr; + /// Stack of currently active analysis timers. Analyses can request other + /// analyses. + SmallVector AnalysisActiveTimerStack; /// Custom output stream to print timing information into. /// By default (== nullptr) we emit time report into the stream created by @@ -89,14 +93,12 @@ class TimePassesHandler { LLVM_DUMP_METHOD void dump() const; /// Returns the new timer for each new run of the pass. - Timer &getPassTimer(StringRef PassID); + Timer &getPassTimer(StringRef PassID, bool IsPass); - void startTimer(StringRef PassID); - void stopTimer(StringRef PassID); - - // Implementation of pass instrumentation callbacks. - void runBeforePass(StringRef PassID); - void runAfterPass(StringRef PassID); + void startAnalysisTimer(StringRef PassID); + void stopAnalysisTimer(StringRef PassID); + void startPassTimer(StringRef PassID); + void stopPassTimer(StringRef PassID); }; } // namespace llvm diff --git a/llvm/lib/IR/PassTimingInfo.cpp b/llvm/lib/IR/PassTimingInfo.cpp index a03fafec9fac0..cfd27bf787937 100644 --- a/llvm/lib/IR/PassTimingInfo.cpp +++ b/llvm/lib/IR/PassTimingInfo.cpp @@ -94,8 +94,7 @@ class PassTimingInfo { static ManagedStatic> TimingInfoMutex; -PassTimingInfo::PassTimingInfo() - : TG("pass", "... Pass execution timing report ...") {} +PassTimingInfo::PassTimingInfo() : TG("pass", "Pass execution timing report") {} PassTimingInfo::~PassTimingInfo() { // Deleting the timers accumulates their info into the TG member. @@ -170,7 +169,8 @@ void reportAndResetTimings(raw_ostream *OutStream) { /// Returns the timer for the specified pass invocation of \p PassID. /// Each time it creates a new timer. -Timer &TimePassesHandler::getPassTimer(StringRef PassID) { +Timer &TimePassesHandler::getPassTimer(StringRef PassID, bool IsPass) { + TimerGroup &TG = IsPass ? PassTG : AnalysisTG; if (!PerRun) { TimerVector &Timers = TimingData[PassID]; if (Timers.size() == 0) @@ -193,8 +193,9 @@ Timer &TimePassesHandler::getPassTimer(StringRef PassID) { } TimePassesHandler::TimePassesHandler(bool Enabled, bool PerRun) - : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled), - PerRun(PerRun) {} + : PassTG("pass", "Pass execution timing report"), + AnalysisTG("analysis", "Analysis execution timing report"), + Enabled(Enabled), PerRun(PerRun) {} TimePassesHandler::TimePassesHandler() : TimePassesHandler(TimePassesIsEnabled, TimePassesPerRun) {} @@ -206,7 +207,16 @@ void TimePassesHandler::setOutStream(raw_ostream &Out) { void TimePassesHandler::print() { if (!Enabled) return; - TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true); + std::unique_ptr MaybeCreated; + raw_ostream *OS = OutStream; + if (OutStream) { + OS = OutStream; + } else { + MaybeCreated = CreateInfoOutputFile(); + OS = &*MaybeCreated; + } + PassTG.print(*OS, true); + AnalysisTG.print(*OS, true); } LLVM_DUMP_METHOD void TimePassesHandler::dump() const { @@ -233,41 +243,57 @@ LLVM_DUMP_METHOD void TimePassesHandler::dump() const { } } -void TimePassesHandler::startTimer(StringRef PassID) { - Timer &MyTimer = getPassTimer(PassID); - TimerStack.push_back(&MyTimer); - if (!MyTimer.isRunning()) - MyTimer.startTimer(); +static bool shouldIgnorePass(StringRef PassID) { + return isSpecialPass(PassID, + {"PassManager", "PassAdaptor", "AnalysisManagerProxy", + "ModuleInlinerWrapperPass", "DevirtSCCRepeatedPass"}); } -void TimePassesHandler::stopTimer(StringRef PassID) { - assert(TimerStack.size() > 0 && "empty stack in popTimer"); - Timer *MyTimer = TimerStack.pop_back_val(); - assert(MyTimer && "timer should be present"); - if (MyTimer->isRunning()) - MyTimer->stopTimer(); +void TimePassesHandler::startPassTimer(StringRef PassID) { + if (shouldIgnorePass(PassID)) + return; + assert(!ActivePassTimer && "should only have one pass timer at a time"); + Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ true); + ActivePassTimer = &MyTimer; + assert(!MyTimer.isRunning()); + MyTimer.startTimer(); } -void TimePassesHandler::runBeforePass(StringRef PassID) { - if (isSpecialPass(PassID, - {"PassManager", "PassAdaptor", "AnalysisManagerProxy"})) +void TimePassesHandler::stopPassTimer(StringRef PassID) { + if (shouldIgnorePass(PassID)) return; + assert(ActivePassTimer); + assert(ActivePassTimer->isRunning()); + ActivePassTimer->stopTimer(); + ActivePassTimer = nullptr; +} - startTimer(PassID); +void TimePassesHandler::startAnalysisTimer(StringRef PassID) { + // Stop the previous analysis timer to prevent double counting when an + // analysis requests another analysis. + if (!AnalysisActiveTimerStack.empty()) { + assert(AnalysisActiveTimerStack.back()->isRunning()); + AnalysisActiveTimerStack.back()->stopTimer(); + } - LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n"); - LLVM_DEBUG(dump()); + Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ false); + AnalysisActiveTimerStack.push_back(&MyTimer); + if (!MyTimer.isRunning()) + MyTimer.startTimer(); } -void TimePassesHandler::runAfterPass(StringRef PassID) { - if (isSpecialPass(PassID, - {"PassManager", "PassAdaptor", "AnalysisManagerProxy"})) - return; - - stopTimer(PassID); +void TimePassesHandler::stopAnalysisTimer(StringRef PassID) { + assert(!AnalysisActiveTimerStack.empty() && "empty stack in popTimer"); + Timer *MyTimer = AnalysisActiveTimerStack.pop_back_val(); + assert(MyTimer && "timer should be present"); + if (MyTimer->isRunning()) + MyTimer->stopTimer(); - LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n"); - LLVM_DEBUG(dump()); + // Restart the previously stopped timer. + if (!AnalysisActiveTimerStack.empty()) { + assert(!AnalysisActiveTimerStack.back()->isRunning()); + AnalysisActiveTimerStack.back()->startTimer(); + } } void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) { @@ -275,19 +301,19 @@ void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) { return; PIC.registerBeforeNonSkippedPassCallback( - [this](StringRef P, Any) { this->runBeforePass(P); }); + [this](StringRef P, Any) { this->startPassTimer(P); }); PIC.registerAfterPassCallback( [this](StringRef P, Any, const PreservedAnalyses &) { - this->runAfterPass(P); + this->stopPassTimer(P); }); PIC.registerAfterPassInvalidatedCallback( [this](StringRef P, const PreservedAnalyses &) { - this->runAfterPass(P); + this->stopPassTimer(P); }); PIC.registerBeforeAnalysisCallback( - [this](StringRef P, Any) { this->runBeforePass(P); }); + [this](StringRef P, Any) { this->startAnalysisTimer(P); }); PIC.registerAfterAnalysisCallback( - [this](StringRef P, Any) { this->runAfterPass(P); }); + [this](StringRef P, Any) { this->stopAnalysisTimer(P); }); } } // namespace llvm diff --git a/llvm/test/Other/time-passes.ll b/llvm/test/Other/time-passes.ll index 852c583fddfc5..f7a0851a69c14 100644 --- a/llvm/test/Other/time-passes.ll +++ b/llvm/test/Other/time-passes.ll @@ -27,29 +27,34 @@ ; TIME-DOUBLE-LICM-DAG: LICMPass #4 ; TIME-DOUBLE-LICM-DAG: LICMPass #5 ; TIME-DOUBLE-LICM-DAG: LICMPass #6 -; TIME-PER_RUN-DAG: LCSSAPass -; TIME-PER_RUN-DAG: LoopSimplifyPass -; TIME-PER_RUN-DAG: ScalarEvolutionAnalysis -; TIME-PER_RUN-DAG: LoopAnalysis -; TIME-PER_RUN-DAG: VerifierPass -; TIME-PER_RUN-DAG: DominatorTreeAnalysis -; TIME-PER_RUN-DAG: TargetLibraryAnalysis +; TIME-PER-RUN-DAG: LCSSAPass +; TIME-PER-RUN-DAG: LoopSimplifyPass +; TIME-PER-RUN-DAG: VerifierPass ; TIME-PER-PASS-DAG: InstCombinePass ; TIME-PER-PASS-DAG: LICMPass ; TIME-PER-PASS-DAG: LCSSAPass ; TIME-PER-PASS-DAG: LoopSimplifyPass -; TIME-PER-PASS-DAG: ScalarEvolutionAnalysis -; TIME-PER-PASS-DAG: LoopAnalysis ; TIME-PER-PASS-DAG: VerifierPass -; TIME-PER-PASS-DAG: DominatorTreeAnalysis -; TIME-PER-PASS-DAG: TargetLibraryAnalysis ; TIME-PER-PASS-NOT: InstCombinePass # ; TIME-PER-PASS-NOT: LICMPass # ; TIME-PER-PASS-NOT: LCSSAPass # ; TIME-PER-PASS-NOT: LoopSimplifyPass # +; TIME-PER-PASS-NOT: VerifierPass # +; TIME: Total{{$}} + +; TIME: Analysis execution timing report +; TIME: Total Execution Time: +; TIME: Name +; TIME-PER-RUN-DAG: ScalarEvolutionAnalysis +; TIME-PER-RUN-DAG: LoopAnalysis +; TIME-PER-RUN-DAG: DominatorTreeAnalysis +; TIME-PER-RUN-DAG: TargetLibraryAnalysis +; TIME-PER-PASS-DAG: ScalarEvolutionAnalysis +; TIME-PER-PASS-DAG: LoopAnalysis +; TIME-PER-PASS-DAG: DominatorTreeAnalysis +; TIME-PER-PASS-DAG: TargetLibraryAnalysis ; TIME-PER-PASS-NOT: ScalarEvolutionAnalysis # ; TIME-PER-PASS-NOT: LoopAnalysis # -; TIME-PER-PASS-NOT: VerifierPass # ; TIME-PER-PASS-NOT: DominatorTreeAnalysis # ; TIME-PER-PASS-NOT: TargetLibraryAnalysis # ; TIME: Total{{$}} diff --git a/llvm/unittests/IR/TimePassesTest.cpp b/llvm/unittests/IR/TimePassesTest.cpp index a6e01c1d90846..e3d2c726bf91e 100644 --- a/llvm/unittests/IR/TimePassesTest.cpp +++ b/llvm/unittests/IR/TimePassesTest.cpp @@ -135,9 +135,9 @@ TEST(TimePassesTest, CustomOut) { // Pretending that passes are running to trigger the timers. PI.runBeforePass(Pass1, M); + PI.runAfterPass(Pass1, M, PreservedAnalyses::all()); PI.runBeforePass(Pass2, M); PI.runAfterPass(Pass2, M, PreservedAnalyses::all()); - PI.runAfterPass(Pass1, M, PreservedAnalyses::all()); // Generating report. TimePasses->print();