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
31using namespace llvm;
32
33#define DEBUG_TYPE "time-passes"
34
35namespace llvm {
36
37bool TimePassesIsEnabled = false;
38bool TimePassesPerRun = false;
39
40static 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
44static 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
49namespace {
50namespace 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.
59class PassTimingInfo {
60public:
61  using PassInstanceID = void *;
62
63private:
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
68public:
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
91private:
92  Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
93};
94
95static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
96
97PassTimingInfo::PassTimingInfo() : TG("pass", "Pass execution timing report") {}
98
99PassTimingInfo::~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
105void 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.
117void PassTimingInfo::print(raw_ostream *OutStream) {
118  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
119}
120
121Timer *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
130Timer *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
148PassTimingInfo *PassTimingInfo::TheTimeInfo;
149} // namespace legacy
150} // namespace
151
152Timer *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.
161void 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.
172Timer &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
195TimePassesHandler::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
200TimePassesHandler::TimePassesHandler()
201    : TimePassesHandler(TimePassesIsEnabled, TimePassesPerRun) {}
202
203void TimePassesHandler::setOutStream(raw_ostream &Out) {
204  OutStream = &Out;
205}
206
207void 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
222LLVM_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
246static bool shouldIgnorePass(StringRef PassID) {
247  return isSpecialPass(PassID,
248                       {"PassManager", "PassAdaptor", "AnalysisManagerProxy",
249                        "ModuleInlinerWrapperPass", "DevirtSCCRepeatedPass"});
250}
251
252void TimePassesHandler::startPassTimer(StringRef PassID) {
253  if (shouldIgnorePass(PassID))
254    return;
255  // Stop the previous pass timer to prevent double counting when a
256  // pass requests another pass.
257  if (!PassActiveTimerStack.empty()) {
258    assert(PassActiveTimerStack.back()->isRunning());
259    PassActiveTimerStack.back()->stopTimer();
260  }
261  Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ true);
262  PassActiveTimerStack.push_back(&MyTimer);
263  assert(!MyTimer.isRunning());
264  MyTimer.startTimer();
265}
266
267void TimePassesHandler::stopPassTimer(StringRef PassID) {
268  if (shouldIgnorePass(PassID))
269    return;
270  assert(!PassActiveTimerStack.empty() && "empty stack in popTimer");
271  Timer *MyTimer = PassActiveTimerStack.pop_back_val();
272  assert(MyTimer && "timer should be present");
273  assert(MyTimer->isRunning());
274  MyTimer->stopTimer();
275
276  // Restart the previously stopped timer.
277  if (!PassActiveTimerStack.empty()) {
278    assert(!PassActiveTimerStack.back()->isRunning());
279    PassActiveTimerStack.back()->startTimer();
280  }
281}
282
283void TimePassesHandler::startAnalysisTimer(StringRef PassID) {
284  // Stop the previous analysis timer to prevent double counting when an
285  // analysis requests another analysis.
286  if (!AnalysisActiveTimerStack.empty()) {
287    assert(AnalysisActiveTimerStack.back()->isRunning());
288    AnalysisActiveTimerStack.back()->stopTimer();
289  }
290
291  Timer &MyTimer = getPassTimer(PassID, /*IsPass*/ false);
292  AnalysisActiveTimerStack.push_back(&MyTimer);
293  if (!MyTimer.isRunning())
294    MyTimer.startTimer();
295}
296
297void TimePassesHandler::stopAnalysisTimer(StringRef PassID) {
298  assert(!AnalysisActiveTimerStack.empty() && "empty stack in popTimer");
299  Timer *MyTimer = AnalysisActiveTimerStack.pop_back_val();
300  assert(MyTimer && "timer should be present");
301  if (MyTimer->isRunning())
302    MyTimer->stopTimer();
303
304  // Restart the previously stopped timer.
305  if (!AnalysisActiveTimerStack.empty()) {
306    assert(!AnalysisActiveTimerStack.back()->isRunning());
307    AnalysisActiveTimerStack.back()->startTimer();
308  }
309}
310
311void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
312  if (!Enabled)
313    return;
314
315  PIC.registerBeforeNonSkippedPassCallback(
316      [this](StringRef P, Any) { this->startPassTimer(P); });
317  PIC.registerAfterPassCallback(
318      [this](StringRef P, Any, const PreservedAnalyses &) {
319        this->stopPassTimer(P);
320      });
321  PIC.registerAfterPassInvalidatedCallback(
322      [this](StringRef P, const PreservedAnalyses &) {
323        this->stopPassTimer(P);
324      });
325  PIC.registerBeforeAnalysisCallback(
326      [this](StringRef P, Any) { this->startAnalysisTimer(P); });
327  PIC.registerAfterAnalysisCallback(
328      [this](StringRef P, Any) { this->stopAnalysisTimer(P); });
329}
330
331} // namespace llvm
332