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/DenseMap.h"
20#include "llvm/ADT/Statistic.h"
21#include "llvm/ADT/StringRef.h"
22#include "llvm/IR/PassInstrumentation.h"
23#include "llvm/Pass.h"
24#include "llvm/Support/CommandLine.h"
25#include "llvm/Support/Debug.h"
26#include "llvm/Support/FormatVariadic.h"
27#include "llvm/Support/ManagedStatic.h"
28#include "llvm/Support/Mutex.h"
29#include "llvm/Support/Timer.h"
30#include "llvm/Support/raw_ostream.h"
31#include <memory>
32#include <string>
33
34using namespace llvm;
35
36#define DEBUG_TYPE "time-passes"
37
38namespace llvm {
39
40bool TimePassesIsEnabled = false;
41
42static cl::opt<bool, true> EnableTiming(
43    "time-passes", cl::location(TimePassesIsEnabled), cl::Hidden,
44    cl::desc("Time each pass, printing elapsed time for each on exit"));
45
46namespace {
47namespace legacy {
48
49//===----------------------------------------------------------------------===//
50// Legacy pass manager's PassTimingInfo implementation
51
52/// Provides an interface for collecting pass timing information.
53///
54/// It was intended to be generic but now we decided to split
55/// interfaces completely. This is now exclusively for legacy-pass-manager use.
56class PassTimingInfo {
57public:
58  using PassInstanceID = void *;
59
60private:
61  StringMap<unsigned> PassIDCountMap; ///< Map that counts instances of passes
62  DenseMap<PassInstanceID, std::unique_ptr<Timer>> TimingData; ///< timers for pass instances
63  TimerGroup TG;
64
65public:
66  /// Default constructor for yet-inactive timeinfo.
67  /// Use \p init() to activate it.
68  PassTimingInfo();
69
70  /// Print out timing information and release timers.
71  ~PassTimingInfo();
72
73  /// Initializes the static \p TheTimeInfo member to a non-null value when
74  /// -time-passes is enabled. Leaves it null otherwise.
75  ///
76  /// This method may be called multiple times.
77  static void init();
78
79  /// Prints out timing information and then resets the timers.
80  /// By default it uses the stream created by CreateInfoOutputFile().
81  void print(raw_ostream *OutStream = nullptr);
82
83  /// Returns the timer for the specified pass if it exists.
84  Timer *getPassTimer(Pass *, PassInstanceID);
85
86  static PassTimingInfo *TheTimeInfo;
87
88private:
89  Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
90};
91
92static ManagedStatic<sys::SmartMutex<true>> TimingInfoMutex;
93
94PassTimingInfo::PassTimingInfo()
95    : TG("pass", "... Pass execution timing report ...") {}
96
97PassTimingInfo::~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
103void 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.
115void PassTimingInfo::print(raw_ostream *OutStream) {
116  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
117}
118
119Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) {
120  unsigned &num = PassIDCountMap[PassID];
121  num++;
122  // Appending description with a pass-instance number for all but the first one
123  std::string PassDescNumbered =
124      num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
125  return new Timer(PassID, PassDescNumbered, TG);
126}
127
128Timer *PassTimingInfo::getPassTimer(Pass *P, PassInstanceID Pass) {
129  if (P->getAsPMDataManager())
130    return nullptr;
131
132  init();
133  sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
134  std::unique_ptr<Timer> &T = TimingData[Pass];
135
136  if (!T) {
137    StringRef PassName = P->getPassName();
138    StringRef PassArgument;
139    if (const PassInfo *PI = Pass::lookupPassInfo(P->getPassID()))
140      PassArgument = PI->getPassArgument();
141    T.reset(newPassTimer(PassArgument.empty() ? PassName : PassArgument, PassName));
142  }
143  return T.get();
144}
145
146PassTimingInfo *PassTimingInfo::TheTimeInfo;
147} // namespace legacy
148} // namespace
149
150Timer *getPassTimer(Pass *P) {
151  legacy::PassTimingInfo::init();
152  if (legacy::PassTimingInfo::TheTimeInfo)
153    return legacy::PassTimingInfo::TheTimeInfo->getPassTimer(P, P);
154  return nullptr;
155}
156
157/// If timing is enabled, report the times collected up to now and then reset
158/// them.
159void reportAndResetTimings(raw_ostream *OutStream) {
160  if (legacy::PassTimingInfo::TheTimeInfo)
161    legacy::PassTimingInfo::TheTimeInfo->print(OutStream);
162}
163
164//===----------------------------------------------------------------------===//
165// Pass timing handling for the New Pass Manager
166//===----------------------------------------------------------------------===//
167
168/// Returns the timer for the specified pass invocation of \p PassID.
169/// Each time it creates a new timer.
170Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
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() && "sanity check");
181
182  return *T;
183}
184
185TimePassesHandler::TimePassesHandler(bool Enabled)
186    : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled) {}
187
188void TimePassesHandler::setOutStream(raw_ostream &Out) {
189  OutStream = &Out;
190}
191
192void TimePassesHandler::print() {
193  if (!Enabled)
194    return;
195  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
196}
197
198LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
199  dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()
200         << ":\n\tRunning:\n";
201  for (auto &I : TimingData) {
202    StringRef PassID = I.getKey();
203    const TimerVector& MyTimers = I.getValue();
204    for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
205      const Timer* MyTimer = MyTimers[idx].get();
206      if (MyTimer && MyTimer->isRunning())
207        dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
208    }
209  }
210  dbgs() << "\tTriggered:\n";
211  for (auto &I : TimingData) {
212    StringRef PassID = I.getKey();
213    const TimerVector& MyTimers = I.getValue();
214    for (unsigned idx = 0; idx < MyTimers.size(); idx++) {
215      const Timer* MyTimer = MyTimers[idx].get();
216      if (MyTimer && MyTimer->hasTriggered() && !MyTimer->isRunning())
217        dbgs() << "\tTimer " << MyTimer << " for pass " << PassID << "(" << idx << ")\n";
218    }
219  }
220}
221
222void TimePassesHandler::startTimer(StringRef PassID) {
223  Timer &MyTimer = getPassTimer(PassID);
224  TimerStack.push_back(&MyTimer);
225  if (!MyTimer.isRunning())
226    MyTimer.startTimer();
227}
228
229void TimePassesHandler::stopTimer(StringRef PassID) {
230  assert(TimerStack.size() > 0 && "empty stack in popTimer");
231  Timer *MyTimer = TimerStack.pop_back_val();
232  assert(MyTimer && "timer should be present");
233  if (MyTimer->isRunning())
234    MyTimer->stopTimer();
235}
236
237static bool matchPassManager(StringRef PassID) {
238  size_t prefix_pos = PassID.find('<');
239  if (prefix_pos == StringRef::npos)
240    return false;
241  StringRef Prefix = PassID.substr(0, prefix_pos);
242  return Prefix.endswith("PassManager") || Prefix.endswith("PassAdaptor") ||
243         Prefix.endswith("AnalysisManagerProxy");
244}
245
246bool TimePassesHandler::runBeforePass(StringRef PassID) {
247  if (matchPassManager(PassID))
248    return true;
249
250  startTimer(PassID);
251
252  LLVM_DEBUG(dbgs() << "after runBeforePass(" << PassID << ")\n");
253  LLVM_DEBUG(dump());
254
255  // we are not going to skip this pass, thus return true.
256  return true;
257}
258
259void TimePassesHandler::runAfterPass(StringRef PassID) {
260  if (matchPassManager(PassID))
261    return;
262
263  stopTimer(PassID);
264
265  LLVM_DEBUG(dbgs() << "after runAfterPass(" << PassID << ")\n");
266  LLVM_DEBUG(dump());
267}
268
269void TimePassesHandler::registerCallbacks(PassInstrumentationCallbacks &PIC) {
270  if (!Enabled)
271    return;
272
273  PIC.registerBeforePassCallback(
274      [this](StringRef P, Any) { return this->runBeforePass(P); });
275  PIC.registerAfterPassCallback(
276      [this](StringRef P, Any) { this->runAfterPass(P); });
277  PIC.registerAfterPassInvalidatedCallback(
278      [this](StringRef P) { this->runAfterPass(P); });
279  PIC.registerBeforeAnalysisCallback(
280      [this](StringRef P, Any) { this->runBeforePass(P); });
281  PIC.registerAfterAnalysisCallback(
282      [this](StringRef P, Any) { this->runAfterPass(P); });
283}
284
285} // namespace llvm
286