1 //===- PassTimingInfo.cpp - LLVM Pass Timing Implementation ---------------===//
2 //
3 //                     The LLVM Compiler Infrastructure
4 //
5 // This file is distributed under the University of Illinois Open Source
6 // License. See LICENSE.TXT for details.
7 //
8 //===----------------------------------------------------------------------===//
9 //
10 // This file implements the LLVM Pass Timing infrastructure for both
11 // new and legacy pass managers.
12 //
13 // PassTimingInfo Class - This class is used to calculate information about the
14 // amount of time each pass takes to execute.  This only happens when
15 // -time-passes is enabled on the command line.
16 //
17 //===----------------------------------------------------------------------===//
18 
19 #include "llvm/IR/PassTimingInfo.h"
20 #include "llvm/ADT/DenseMap.h"
21 #include "llvm/ADT/Statistic.h"
22 #include "llvm/ADT/StringRef.h"
23 #include "llvm/IR/PassInstrumentation.h"
24 #include "llvm/Pass.h"
25 #include "llvm/Support/CommandLine.h"
26 #include "llvm/Support/Debug.h"
27 #include "llvm/Support/FormatVariadic.h"
28 #include "llvm/Support/ManagedStatic.h"
29 #include "llvm/Support/Mutex.h"
30 #include "llvm/Support/Timer.h"
31 #include "llvm/Support/raw_ostream.h"
32 #include <memory>
33 #include <string>
34 
35 using namespace llvm;
36 
37 #define DEBUG_TYPE "time-passes"
38 
39 namespace llvm {
40 
41 bool TimePassesIsEnabled = false;
42 
43 static cl::opt<bool, true> EnableTiming(
44     "time-passes", cl::location(TimePassesIsEnabled), cl::Hidden,
45     cl::desc("Time each pass, printing elapsed time for each on exit"));
46 
47 namespace {
48 namespace legacy {
49 
50 //===----------------------------------------------------------------------===//
51 // Legacy pass manager's PassTimingInfo implementation
52 
53 /// Provides an interface for collecting pass timing information.
54 ///
55 /// It was intended to be generic but now we decided to split
56 /// interfaces completely. This is now exclusively for legacy-pass-manager use.
57 class PassTimingInfo {
58 public:
59   using PassInstanceID = void *;
60 
61 private:
62   StringMap<unsigned> PassIDCountMap; ///< Map that counts instances of passes
63   DenseMap<PassInstanceID, std::unique_ptr<Timer>> TimingData; ///< timers for pass instances
64   TimerGroup TG;
65 
66 public:
67   /// Default constructor for yet-inactive timeinfo.
68   /// Use \p init() to activate it.
69   PassTimingInfo();
70 
71   /// Print out timing information and release timers.
72   ~PassTimingInfo();
73 
74   /// Initializes the static \p TheTimeInfo member to a non-null value when
75   /// -time-passes is enabled. Leaves it null otherwise.
76   ///
77   /// This method may be called multiple times.
78   static void init();
79 
80   /// Prints out timing information and then resets the timers.
81   void print();
82 
83   /// Returns the timer for the specified pass if it exists.
84   Timer *getPassTimer(Pass *, PassInstanceID);
85 
86   static PassTimingInfo *TheTimeInfo;
87 
88 private:
89   Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
90 };
91 
92 static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
93 
94 PassTimingInfo::PassTimingInfo()
95     : TG("pass", "... Pass execution timing report ...") {}
96 
97 PassTimingInfo::~PassTimingInfo() {
98   // Deleting the timers accumulates their info into the TG member.
99   // Then TG member is (implicitly) deleted, actually printing the report.
100   TimingData.clear();
101 }
102 
103 void PassTimingInfo::init() {
104   if (!TimePassesIsEnabled || TheTimeInfo)
105     return;
106 
107   // Constructed the first time this is called, iff -time-passes is enabled.
108   // This guarantees that the object will be constructed after static globals,
109   // thus it will be destroyed before them.
110   static ManagedStatic<PassTimingInfo> TTI;
111   TheTimeInfo = &*TTI;
112 }
113 
114 /// Prints out timing information and then resets the timers.
115 void PassTimingInfo::print() { TG.print(*CreateInfoOutputFile()); }
116 
117 Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) {
118   unsigned &num = PassIDCountMap[PassID];
119   num++;
120   // Appending description with a pass-instance number for all but the first one
121   std::string PassDescNumbered =
122       num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
123   return new Timer(PassID, PassDescNumbered, TG);
124 }
125 
126 Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) {
127   if (P->getAsPMDataManager())
128     return nullptr;
129 
130   init();
131   sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
132   std::unique_ptr<Timer> &T = TimingData[Pass];
133 
134   if (!T) {
135     StringRef PassName = P->getPassName();
136     StringRef PassArgument;
137     if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID()))
138       PassArgument = PI->getPassArgument();
139     T.reset(newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName));
140   }
141   return T.get();
142 }
143 
144 PassTimingInfo *PassTimingInfo::TheTimeInfo;
145 } // namespace legacy
146 } // namespace
147 
148 Timer *getPassTimer(Pass *P) {
149   legacy::PassTimingInfo::init();
150   if (legacy::PassTimingInfo::TheTimeInfo)
151     return legacy::PassTimingInfo::TheTimeInfo->getPassTimer(P, P);
152   return nullptr;
153 }
154 
155 /// If timing is enabled, report the times collected up to now and then reset
156 /// them.
157 void reportAndResetTimings() {
158   if (legacy::PassTimingInfo::TheTimeInfo)
159     legacy::PassTimingInfo::TheTimeInfo->print();
160 }
161 
162 //===----------------------------------------------------------------------===//
163 // Pass timing handling for the New Pass Manager
164 //===----------------------------------------------------------------------===//
165 
166 /// Returns the timer for the specified pass invocation of \p PassID.
167 /// Each time it creates a new timer.
168 Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
169   // Bump counts for each request of the timer.
170   unsigned Count = nextPassID(PassID);
171 
172   // Unconditionally appending description with a pass-invocation number.
173   std::string FullDesc = formatv("{0} #{1}", PassID, Count).str();
174 
175   PassInvocationID UID{PassID, Count};
176   Timer *T = new Timer(PassID, FullDesc, TG);
177   auto Pair = TimingData.try_emplace(UID, T);
178   assert(Pair.second && "should always create a new timer");
179   return *(Pair.first->second.get());
180 }
181 
182 TimePassesHandler::TimePassesHandler(bool Enabled)
183     : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled) {}
184 
185 void TimePassesHandler::print() { TG.print(*CreateInfoOutputFile()); }
186 
187 LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
188   dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
189          << ":\n\tRunning:\n";
190   for (auto &I : TimingData) {
191     const Timer *MyTimer = I.second.get();
192     if (!MyTimer || MyTimer->isRunning())
193       dbgs() << "\tTimer " << MyTimer << " for pass " << I.first.first << "("
194              << I.first.second << ")\n";
195   }
196   dbgs() << "\tTriggered:\n";
197   for (auto &I : TimingData) {
198     const Timer *MyTimer = I.second.get();
199     if (!MyTimer || (MyTimer->hasTriggered() && !MyTimer->isRunning()))
200       dbgs() << "\tTimer " << MyTimer << " for pass " << I.first.first << "("
201              << I.first.second << ")\n";
202   }
203 }
204 
205 void TimePassesHandler::startTimer(StringRef PassID) {
206   Timer &MyTimer = getPassTimer(PassID);
207   TimerStack.push_back(&MyTimer);
208   if (!MyTimer.isRunning())
209     MyTimer.startTimer();
210 }
211 
212 void TimePassesHandler::stopTimer(StringRef PassID) {
213   assert(TimerStack.size() > 0 && "empty stack in popTimer");
214   Timer *MyTimer = TimerStack.pop_back_val();
215   assert(MyTimer && "timer should be present");
216   if (MyTimer->isRunning())
217     MyTimer->stopTimer();
218 }
219 
220 static bool matchPassManager(StringRef PassID) {
221   size_t prefix_pos = PassID.find('<');
222   if (prefix_pos == StringRef::npos)
223     return false;
224   StringRef Prefix = PassID.substr(0, prefix_pos);
225   return Prefix.endswith("PassManager") || Prefix.endswith("PassAdaptor") ||
226          Prefix.endswith("AnalysisManagerProxy");
227 }
228 
229 bool TimePassesHandler::runBeforePass(StringRef PassID) {
230   if (matchPassManager(PassID))
231     return true;
232 
233   startTimer(PassID);
234 
235   LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n");
236   LLVM_DEBUG(dump());
237 
238   // we are not going to skip this pass, thus return true.
239   return true;
240 }
241 
242 void TimePassesHandler::runAfterPass(StringRef PassID) {
243   if (matchPassManager(PassID))
244     return;
245 
246   stopTimer(PassID);
247 
248   LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n");
249   LLVM_DEBUG(dump());
250 }
251 
252 void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
253   if (!Enabled)
254     return;
255 
256   PIC.registerBeforePassCallback(
257       [this](StringRef P, Any) { return this->runBeforePass(P); });
258   PIC.registerAfterPassCallback(
259       [this](StringRef P, Any) { this->runAfterPass(P); });
260   PIC.registerAfterPassInvalidatedCallback(
261       [this](StringRef P) { this->runAfterPass(P); });
262   PIC.registerBeforeAnalysisCallback(
263       [this](StringRef P, Any) { this->runBeforePass(P); });
264   PIC.registerAfterAnalysisCallback(
265       [this](StringRef P, Any) { this->runAfterPass(P); });
266 }
267 
268 } // namespace llvm
269