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"),
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 TG;
67 
68 public:
69   /// Default constructor for yet-inactive timeinfo.
70   /// Use \p init() to activate it.
71   PassTimingInfo();
72 
73   /// Print out timing information and release timers.
74   ~PassTimingInfo();
75 
76   /// Initializes the static \p TheTimeInfo member to a non-null value when
77   /// -time-passes is enabled. Leaves it null otherwise.
78   ///
79   /// This method may be called multiple times.
80   static void init();
81 
82   /// Prints out timing information and then resets the timers.
83   /// By default it uses the stream created by CreateInfoOutputFile().
84   void print(raw_ostream *OutStream = nullptr);
85 
86   /// Returns the timer for the specified pass if it exists.
87   Timer *getPassTimer(Pass *, PassInstanceID);
88 
89   static PassTimingInfo *TheTimeInfo;
90 
91 private:
92   Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
93 };
94 
95 static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
96 
97 PassTimingInfo::PassTimingInfo() : TG("pass", "Pass execution timing report") {}
98 
99 PassTimingInfo::~PassTimingInfo() {
100   // Deleting the timers accumulates their info into the TG member.
101   // Then TG member is (implicitly) deleted, actually printing the report.
102   TimingData.clear();
103 }
104 
105 void PassTimingInfo::init() {
106   if (!TimePassesIsEnabled || TheTimeInfo)
107     return;
108 
109   // Constructed the first time this is called, iff -time-passes is enabled.
110   // This guarantees that the object will be constructed after static globals,
111   // thus it will be destroyed before them.
112   static ManagedStatic<PassTimingInfo> TTI;
113   TheTimeInfo = &*TTI;
114 }
115 
116 /// Prints out timing information and then resets the timers.
117 void PassTimingInfo::print(raw_ostream *OutStream) {
118   TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
119 }
120 
121 Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) {
122   unsigned &num = PassIDCountMap[PassID];
123   num++;
124   // Appending description with a pass-instance number for all but the first one
125   std::string PassDescNumbered =
126       num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
127   return new Timer(PassID, PassDescNumbered, TG);
128 }
129 
130 Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) {
131   if (P->getAsPMDataManager())
132     return nullptr;
133 
134   init();
135   sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
136   std::unique_ptr<Timer> &T = TimingData[Pass];
137 
138   if (!T) {
139     StringRef PassName = P->getPassName();
140     StringRef PassArgument;
141     if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID()))
142       PassArgument = PI->getPassArgument();
143     T.reset(newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName));
144   }
145   return T.get();
146 }
147 
148 PassTimingInfo *PassTimingInfo::TheTimeInfo;
149 } // namespace legacy
150 } // namespace
151 
152 Timer *getPassTimer(Pass *P) {
153   legacy::PassTimingInfo::init();
154   if (legacy::PassTimingInfo::TheTimeInfo)
155     return legacy::PassTimingInfo::TheTimeInfo->getPassTimer(P, P);
156   return nullptr;
157 }
158 
159 /// If timing is enabled, report the times collected up to now and then reset
160 /// them.
161 void reportAndResetTimings(raw_ostream *OutStream) {
162   if (legacy::PassTimingInfo::TheTimeInfo)
163     legacy::PassTimingInfo::TheTimeInfo->print(OutStream);
164 }
165 
166 //===----------------------------------------------------------------------===//
167 // Pass timing handling for the New Pass Manager
168 //===----------------------------------------------------------------------===//
169 
170 /// Returns the timer for the specified pass invocation of \p PassID.
171 /// Each time it creates a new timer.
172 Timer &TimePassesHandler::getPassTimer(StringRef PassID, bool IsPass) {
173   TimerGroup &TG = IsPass ? PassTG : AnalysisTG;
174   if (!PerRun) {
175     TimerVector &Timers = TimingData[PassID];
176     if (Timers.size() == 0)
177       Timers.emplace_back(new Timer(PassID, PassID, TG));
178     return *Timers.front();
179   }
180 
181   // Take a vector of Timers created for this \p PassID and append
182   // one more timer to it.
183   TimerVector &Timers = TimingData[PassID];
184   unsigned Count = Timers.size() + 1;
185 
186   std::string FullDesc = formatv("{0} #{1}", PassID, Count).str();
187 
188   Timer *T = new Timer(PassID, FullDesc, TG);
189   Timers.emplace_back(T);
190   assert(Count == Timers.size() && "Timers vector not adjusted correctly.");
191 
192   return *T;
193 }
194 
195 TimePassesHandler::TimePassesHandler(bool Enabled, bool PerRun)
196     : PassTG("pass", "Pass execution timing report"),
197       AnalysisTG("analysis", "Analysis execution timing report"),
198       Enabled(Enabled), PerRun(PerRun) {}
199 
200 TimePassesHandler::TimePassesHandler()
201     : TimePassesHandler(TimePassesIsEnabled, TimePassesPerRun) {}
202 
203 void TimePassesHandler::setOutStream(raw_ostream &Out) {
204   OutStream = &Out;
205 }
206 
207 void TimePassesHandler::print() {
208   if (!Enabled)
209     return;
210   std::unique_ptr<raw_ostream> MaybeCreated;
211   raw_ostream *OS = OutStream;
212   if (OutStream) {
213     OS = OutStream;
214   } else {
215     MaybeCreated = CreateInfoOutputFile();
216     OS = &*MaybeCreated;
217   }
218   PassTG.print(*OS, true);
219   AnalysisTG.print(*OS, true);
220 }
221 
222 LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
223   dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
224          << ":\n\tRunning:\n";
225   for (auto &I : TimingData) {
226     StringRef PassID = I.getKey();
227     const TimerVector& MyTimers = I.getValue();
228     for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
229       const Timer* MyTimer = MyTimers[idx].get();
230       if (MyTimer && MyTimer->isRunning())
231         dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
232     }
233   }
234   dbgs() << "\tTriggered:\n";
235   for (auto &I : TimingData) {
236     StringRef PassID = I.getKey();
237     const TimerVector& MyTimers = I.getValue();
238     for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
239       const Timer* MyTimer = MyTimers[idx].get();
240       if (MyTimer && MyTimer->hasTriggered() && !MyTimer->isRunning())
241         dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
242     }
243   }
244 }
245 
246 static bool shouldIgnorePass(StringRef PassID) {
247   return isSpecialPass(PassID,
248                        {"PassManager", "PassAdaptor", "AnalysisManagerProxy",
249                         "ModuleInlinerWrapperPass", "DevirtSCCRepeatedPass"});
250 }
251 
252 void TimePassesHandler::startPassTimer(StringRef PassID) {
253   if (shouldIgnorePass(PassID))
254     return;
255   assert(!ActivePassTimer && "should only have one pass timer at a time");
256   Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ true);
257   ActivePassTimer = &MyTimer;
258   assert(!MyTimer.isRunning());
259   MyTimer.startTimer();
260 }
261 
262 void TimePassesHandler::stopPassTimer(StringRef PassID) {
263   if (shouldIgnorePass(PassID))
264     return;
265   assert(ActivePassTimer);
266   assert(ActivePassTimer->isRunning());
267   ActivePassTimer->stopTimer();
268   ActivePassTimer = nullptr;
269 }
270 
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 
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 
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