llvm/lib/IR/PassTimingInfo.cpp

   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