1 //===- PassTimingInfo.cpp - LLVM Pass Timing Implementation ---------------===//
2 //
3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4 // See https://llvm.org/LICENSE.txt for license information.
5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6 //
7 //===----------------------------------------------------------------------===//
8 //
9 // This file implements the LLVM Pass Timing infrastructure for both
10 // new and legacy pass managers.
11 //
12 // PassTimingInfo Class - This class is used to calculate information about the
13 // amount of time each pass takes to execute. This only happens when
14 // -time-passes is enabled on the command line.
15 //
16 //===----------------------------------------------------------------------===//
17
18 #include "llvm/IR/PassTimingInfo.h"
19 #include "llvm/ADT/Statistic.h"
20 #include "llvm/IR/PassInstrumentation.h"
21 #include "llvm/Pass.h"
22 #include "llvm/Support/CommandLine.h"
23 #include "llvm/Support/Debug.h"
24 #include "llvm/Support/FormatVariadic.h"
25 #include "llvm/Support/ManagedStatic.h"
26 #include "llvm/Support/Mutex.h"
27 #include "llvm/Support/TypeName.h"
28 #include "llvm/Support/raw_ostream.h"
29 #include <string>
30
31 using namespace llvm;
32
33 #define DEBUG_TYPE "time-passes"
34
35 namespace llvm {
36
37 bool TimePassesIsEnabled = false;
38 bool TimePassesPerRun = false;
39
40 static cl::opt<bool, true> EnableTiming(
41 "time-passes", cl::location(TimePassesIsEnabled), cl::Hidden,
42 cl::desc("Time each pass, printing elapsed time for each on exit"));
43
44 static cl::opt<bool, true> EnableTimingPerRun(
45 "time-passes-per-run", cl::location(TimePassesPerRun), cl::Hidden,
46 cl::desc("Time each pass run, printing elapsed time for each run on exit"),
__anon2e7fb3850102(const bool &) 47 cl::callback([](const bool &) { TimePassesIsEnabled = true; }));
48
49 namespace {
50 namespace legacy {
51
52 //===----------------------------------------------------------------------===//
53 // Legacy pass manager's PassTimingInfo implementation
54
55 /// Provides an interface for collecting pass timing information.
56 ///
57 /// It was intended to be generic but now we decided to split
58 /// interfaces completely. This is now exclusively for legacy-pass-manager use.
59 class PassTimingInfo {
60 public:
61 using PassInstanceID = void *;
62
63 private:
64 StringMap<unsigned> PassIDCountMap; ///< Map that counts instances of passes
65 DenseMap<PassInstanceID, std::unique_ptr<Timer>> TimingData; ///< timers for pass instances
66 TimerGroup *PassTG = nullptr;
67
68 public:
69 /// Initializes the static \p TheTimeInfo member to a non-null value when
70 /// -time-passes is enabled. Leaves it null otherwise.
71 ///
72 /// This method may be called multiple times.
73 static void init();
74
75 /// Prints out timing information and then resets the timers.
76 /// By default it uses the stream created by CreateInfoOutputFile().
77 void print(raw_ostream *OutStream = nullptr);
78
79 /// Returns the timer for the specified pass if it exists.
80 Timer *getPassTimer(Pass *, PassInstanceID);
81
82 static PassTimingInfo *TheTimeInfo;
83
84 private:
85 Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
86 };
87
88 static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
89
init()90 void PassTimingInfo::init() {
91 if (TheTimeInfo || !TimePassesIsEnabled)
92 return;
93
94 // Constructed the first time this is called, iff -time-passes is enabled.
95 // This guarantees that the object will be constructed after static globals,
96 // thus it will be destroyed before them.
97 static ManagedStatic<PassTimingInfo> TTI;
98 if (!TTI->PassTG)
99 TTI->PassTG = &NamedRegionTimer::getNamedTimerGroup(
100 TimePassesHandler::PassGroupName, TimePassesHandler::PassGroupDesc);
101 TheTimeInfo = &*TTI;
102 }
103
104 /// Prints out timing information and then resets the timers.
print(raw_ostream * OutStream)105 void PassTimingInfo::print(raw_ostream *OutStream) {
106 assert(PassTG && "PassTG is null, did you call PassTimingInfo::Init()?");
107 PassTG->print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
108 }
109
newPassTimer(StringRef PassID,StringRef PassDesc)110 Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) {
111 unsigned &num = PassIDCountMap[PassID];
112 num++;
113 // Appending description with a pass-instance number for all but the first one
114 std::string PassDescNumbered =
115 num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
116 assert(PassTG && "PassTG is null, did you call PassTimingInfo::Init()?");
117 return new Timer(PassID, PassDescNumbered, *PassTG);
118 }
119
getPassTimer(Pass * P,PassInstanceID Pass)120 Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) {
121 if (P->getAsPMDataManager())
122 return nullptr;
123
124 init();
125 sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
126 std::unique_ptr<Timer> &T = TimingData[Pass];
127
128 if (!T) {
129 StringRef PassName = P->getPassName();
130 StringRef PassArgument;
131 if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID()))
132 PassArgument = PI->getPassArgument();
133 T.reset(newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName));
134 }
135 return T.get();
136 }
137
138 PassTimingInfo *PassTimingInfo::TheTimeInfo;
139 } // namespace legacy
140 } // namespace
141
getPassTimer(Pass * P)142 Timer *getPassTimer(Pass *P) {
143 legacy::PassTimingInfo::init();
144 if (legacy::PassTimingInfo::TheTimeInfo)
145 return legacy::PassTimingInfo::TheTimeInfo->getPassTimer(P, P);
146 return nullptr;
147 }
148
149 /// If timing is enabled, report the times collected up to now and then reset
150 /// them.
reportAndResetTimings(raw_ostream * OutStream)151 void reportAndResetTimings(raw_ostream *OutStream) {
152 if (legacy::PassTimingInfo::TheTimeInfo)
153 legacy::PassTimingInfo::TheTimeInfo->print(OutStream);
154 }
155
156 //===----------------------------------------------------------------------===//
157 // Pass timing handling for the New Pass Manager
158 //===----------------------------------------------------------------------===//
159
160 /// Returns the timer for the specified pass invocation of \p PassID.
161 /// Each time it creates a new timer.
getPassTimer(StringRef PassID,bool IsPass)162 Timer &TimePassesHandler::getPassTimer(StringRef PassID, bool IsPass) {
163 TimerGroup &TG = IsPass ? PassTG : AnalysisTG;
164 if (!PerRun) {
165 TimerVector &Timers = TimingData[PassID];
166 if (Timers.size() == 0)
167 Timers.emplace_back(new Timer(PassID, PassID, TG));
168 return *Timers.front();
169 }
170
171 // Take a vector of Timers created for this \p PassID and append
172 // one more timer to it.
173 TimerVector &Timers = TimingData[PassID];
174 unsigned Count = Timers.size() + 1;
175
176 std::string FullDesc = formatv("{0} #{1}", PassID, Count).str();
177
178 Timer *T = new Timer(PassID, FullDesc, TG);
179 Timers.emplace_back(T);
180 assert(Count == Timers.size() && "Timers vector not adjusted correctly.");
181
182 return *T;
183 }
184
TimePassesHandler(bool Enabled,bool PerRun)185 TimePassesHandler::TimePassesHandler(bool Enabled, bool PerRun)
186 : Enabled(Enabled), PerRun(PerRun) {}
187
TimePassesHandler()188 TimePassesHandler::TimePassesHandler()
189 : TimePassesHandler(TimePassesIsEnabled, TimePassesPerRun) {}
190
setOutStream(raw_ostream & Out)191 void TimePassesHandler::setOutStream(raw_ostream &Out) {
192 OutStream = &Out;
193 }
194
print()195 void TimePassesHandler::print() {
196 if (!Enabled)
197 return;
198 std::unique_ptr<raw_ostream> MaybeCreated;
199 raw_ostream *OS = OutStream;
200 if (OutStream) {
201 OS = OutStream;
202 } else {
203 MaybeCreated = CreateInfoOutputFile();
204 OS = &*MaybeCreated;
205 }
206 PassTG.print(*OS, true);
207 AnalysisTG.print(*OS, true);
208 }
209
dump() const210 LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
211 dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
212 << ":\n\tRunning:\n";
213 for (auto &I : TimingData) {
214 StringRef PassID = I.getKey();
215 const TimerVector& MyTimers = I.getValue();
216 for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
217 const Timer* MyTimer = MyTimers[idx].get();
218 if (MyTimer && MyTimer->isRunning())
219 dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
220 }
221 }
222 dbgs() << "\tTriggered:\n";
223 for (auto &I : TimingData) {
224 StringRef PassID = I.getKey();
225 const TimerVector& MyTimers = I.getValue();
226 for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
227 const Timer* MyTimer = MyTimers[idx].get();
228 if (MyTimer && MyTimer->hasTriggered() && !MyTimer->isRunning())
229 dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
230 }
231 }
232 }
233
shouldIgnorePass(StringRef PassID)234 static bool shouldIgnorePass(StringRef PassID) {
235 return isSpecialPass(PassID,
236 {"PassManager", "PassAdaptor", "AnalysisManagerProxy",
237 "ModuleInlinerWrapperPass", "DevirtSCCRepeatedPass"});
238 }
239
startPassTimer(StringRef PassID)240 void TimePassesHandler::startPassTimer(StringRef PassID) {
241 if (shouldIgnorePass(PassID))
242 return;
243 // Stop the previous pass timer to prevent double counting when a
244 // pass requests another pass.
245 if (!PassActiveTimerStack.empty()) {
246 assert(PassActiveTimerStack.back()->isRunning());
247 PassActiveTimerStack.back()->stopTimer();
248 }
249 Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ true);
250 PassActiveTimerStack.push_back(&MyTimer);
251 assert(!MyTimer.isRunning());
252 MyTimer.startTimer();
253 }
254
stopPassTimer(StringRef PassID)255 void TimePassesHandler::stopPassTimer(StringRef PassID) {
256 if (shouldIgnorePass(PassID))
257 return;
258 assert(!PassActiveTimerStack.empty() && "empty stack in popTimer");
259 Timer *MyTimer = PassActiveTimerStack.pop_back_val();
260 assert(MyTimer && "timer should be present");
261 assert(MyTimer->isRunning());
262 MyTimer->stopTimer();
263
264 // Restart the previously stopped timer.
265 if (!PassActiveTimerStack.empty()) {
266 assert(!PassActiveTimerStack.back()->isRunning());
267 PassActiveTimerStack.back()->startTimer();
268 }
269 }
270
startAnalysisTimer(StringRef PassID)271 void TimePassesHandler::startAnalysisTimer(StringRef PassID) {
272 // Stop the previous analysis timer to prevent double counting when an
273 // analysis requests another analysis.
274 if (!AnalysisActiveTimerStack.empty()) {
275 assert(AnalysisActiveTimerStack.back()->isRunning());
276 AnalysisActiveTimerStack.back()->stopTimer();
277 }
278
279 Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ false);
280 AnalysisActiveTimerStack.push_back(&MyTimer);
281 if (!MyTimer.isRunning())
282 MyTimer.startTimer();
283 }
284
stopAnalysisTimer(StringRef PassID)285 void TimePassesHandler::stopAnalysisTimer(StringRef PassID) {
286 assert(!AnalysisActiveTimerStack.empty() && "empty stack in popTimer");
287 Timer *MyTimer = AnalysisActiveTimerStack.pop_back_val();
288 assert(MyTimer && "timer should be present");
289 if (MyTimer->isRunning())
290 MyTimer->stopTimer();
291
292 // Restart the previously stopped timer.
293 if (!AnalysisActiveTimerStack.empty()) {
294 assert(!AnalysisActiveTimerStack.back()->isRunning());
295 AnalysisActiveTimerStack.back()->startTimer();
296 }
297 }
298
registerCallbacks(PassInstrumentationCallbacks & PIC)299 void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
300 if (!Enabled)
301 return;
302
303 PIC.registerBeforeNonSkippedPassCallback(
304 [this](StringRef P, Any) { this->startPassTimer(P); });
305 PIC.registerAfterPassCallback(
306 [this](StringRef P, Any, const PreservedAnalyses &) {
307 this->stopPassTimer(P);
308 });
309 PIC.registerAfterPassInvalidatedCallback(
310 [this](StringRef P, const PreservedAnalyses &) {
311 this->stopPassTimer(P);
312 });
313 PIC.registerBeforeAnalysisCallback(
314 [this](StringRef P, Any) { this->startAnalysisTimer(P); });
315 PIC.registerAfterAnalysisCallback(
316 [this](StringRef P, Any) { this->stopAnalysisTimer(P); });
317 }
318
319 } // namespace llvm
320