[llvm] 0cd27cd - [PassTimingInfo] Stop double (or worse) counting passes/analyses
Arthur Eubanks via llvm-commits
llvm-commits at lists.llvm.org
Thu Oct 13 09:13:40 PDT 2022
Author: Arthur Eubanks
Date: 2022-10-13T09:12:12-07:00
New Revision: 0cd27cdc3adaff1f94bce12d8fbc6b80cb4049a4
URL: https://github.com/llvm/llvm-project/commit/0cd27cdc3adaff1f94bce12d8fbc6b80cb4049a4
DIFF: https://github.com/llvm/llvm-project/commit/0cd27cdc3adaff1f94bce12d8fbc6b80cb4049a4.diff
LOG: [PassTimingInfo] Stop double (or worse) counting passes/analyses
If we nest timers, we end up double counting anything nested.
The most egregious is ModuleInlinerWrapperPass/DevirtSCCRepeatedPass showing up as >20% of the total time when they're just wrappers.
Analyses also end up getting counted multiple times because they're nested inside wrappers and passes.
Ignore ModuleInlinerWrapperPass/DevirtSCCRepeatedPass and put analyses into their own TimerGroup.
Reviewed By: asbirlea
Differential Revision: https://reviews.llvm.org/D135219
Added:
Modified:
llvm/include/llvm/IR/PassTimingInfo.h
llvm/lib/IR/PassTimingInfo.cpp
llvm/test/Other/time-passes.ll
llvm/unittests/IR/TimePassesTest.cpp
Removed:
################################################################################
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<StringRef, unsigned>;
- /// A group of all pass-timing timers.
- TimerGroup TG;
+ /// Groups of timers for passes and analyses.
+ TimerGroup PassTG;
+ TimerGroup AnalysisTG;
using TimerVector = llvm::SmallVector<std::unique_ptr<Timer>, 4>;
/// Map of timers for pass invocations
StringMap<TimerVector> TimingData;
- /// Stack of currently active timers.
- SmallVector<Timer *, 8> TimerStack;
+ /// Currently active pass timer.
+ Timer *ActivePassTimer = nullptr;
+ /// Stack of currently active analysis timers. Analyses can request other
+ /// analyses.
+ SmallVector<Timer *, 8> 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<sys::SmartMutex<true>> 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<raw_ostream> 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();
More information about the llvm-commits
mailing list