lib/Support/Timer.cpp

   1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
   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 /// \file Interval Timing implementation.
  11 //
  12 //===----------------------------------------------------------------------===//
  13
  14 #include "llvm/Support/Timer.h"
  15 #include "llvm/ADT/Statistic.h"
  16 #include "llvm/ADT/StringMap.h"
  17 #include "llvm/Support/CommandLine.h"
  18 #include "llvm/Support/FileSystem.h"
  19 #include "llvm/Support/Format.h"
  20 #include "llvm/Support/ManagedStatic.h"
  21 #include "llvm/Support/Mutex.h"
  22 #include "llvm/Support/Process.h"
  23 #include "llvm/Support/YAMLTraits.h"
  24 #include "llvm/Support/raw_ostream.h"
  25 #include <limits>
  26
  27 using namespace llvm;
  28
  29 // This ugly hack is brought to you courtesy of constructor/destructor ordering
  30 // being unspecified by C++.  Basically the problem is that a Statistic object
  31 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
  32 // (below), which calls this function.  LibSupportInfoOutputFilename used to be
  33 // a global variable, but sometimes it would get destroyed before the Statistic,
  34 // causing havoc to ensue.  We "fix" this by creating the string the first time
  35 // it is needed and never destroying it.
  36 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
  37 static std::string &getLibSupportInfoOutputFilename() {
  38   return *LibSupportInfoOutputFilename;
  39 }
  40
  41 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
  42
  43 namespace {
  44   static cl::opt<bool>
  45   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
  46                                       "tracking (this may be slow)"),
  47              cl::Hidden);
  48
  49   static cl::opt<std::string, true>
  50   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
  51                      cl::desc("File to append -stats and -timer output to"),
  52                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
  53 }
  54
  55 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
  56   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
  57   if (OutputFilename.empty())
  58     return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
  59   if (OutputFilename == "-")
  60     return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
  61
  62   // Append mode is used because the info output file is opened and closed
  63   // each time -stats or -time-passes wants to print output to it. To
  64   // compensate for this, the test-suite Makefiles have code to delete the
  65   // info output file before running commands which write to it.
  66   std::error_code EC;
  67   auto Result = llvm::make_unique<raw_fd_ostream>(
  68       OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
  69   if (!EC)
  70     return Result;
  71
  72   errs() << "Error opening info-output-file '"
  73     << OutputFilename << " for appending!\n";
  74   return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
  75 }
  76
  77 namespace {
  78 struct CreateDefaultTimerGroup {
  79   static void *call() {
  80     return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
  81   }
  82 };
  83 } // namespace
  84 static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
  85 static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
  86
  87 //===----------------------------------------------------------------------===//
  88 // Timer Implementation
  89 //===----------------------------------------------------------------------===//
  90
  91 void Timer::init(StringRef Name, StringRef Description) {
  92   init(Name, Description, *getDefaultTimerGroup());
  93 }
  94
  95 void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
  96   assert(!TG && "Timer already initialized");
  97   this->Name.assign(Name.begin(), Name.end());
  98   this->Description.assign(Description.begin(), Description.end());
  99   Running = Triggered = false;
 100   TG = &tg;
 101   TG->addTimer(*this);
 102 }
 103
 104 Timer::~Timer() {
 105   if (!TG) return;  // Never initialized, or already cleared.
 106   TG->removeTimer(*this);
 107 }
 108
 109 static inline size_t getMemUsage() {
 110   if (!TrackSpace) return 0;
 111   return sys::Process::GetMallocUsage();
 112 }
 113
 114 TimeRecord TimeRecord::getCurrentTime(bool Start) {
 115   using Seconds = std::chrono::duration<double, std::ratio<1>>;
 116   TimeRecord Result;
 117   sys::TimePoint<> now;
 118   std::chrono::nanoseconds user, sys;
 119
 120   if (Start) {
 121     Result.MemUsed = getMemUsage();
 122     sys::Process::GetTimeUsage(now, user, sys);
 123   } else {
 124     sys::Process::GetTimeUsage(now, user, sys);
 125     Result.MemUsed = getMemUsage();
 126   }
 127
 128   Result.WallTime = Seconds(now.time_since_epoch()).count();
 129   Result.UserTime = Seconds(user).count();
 130   Result.SystemTime = Seconds(sys).count();
 131   return Result;
 132 }
 133
 134 void Timer::startTimer() {
 135   assert(!Running && "Cannot start a running timer");
 136   Running = Triggered = true;
 137   StartTime = TimeRecord::getCurrentTime(true);
 138 }
 139
 140 void Timer::stopTimer() {
 141   assert(Running && "Cannot stop a paused timer");
 142   Running = false;
 143   Time += TimeRecord::getCurrentTime(false);
 144   Time -= StartTime;
 145 }
 146
 147 void Timer::clear() {
 148   Running = Triggered = false;
 149   Time = StartTime = TimeRecord();
 150 }
 151
 152 static void printVal(double Val, double Total, raw_ostream &OS) {
 153   if (Total < 1e-7)   // Avoid dividing by zero.
 154     OS << "        -----     ";
 155   else
 156     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
 157 }
 158
 159 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
 160   if (Total.getUserTime())
 161     printVal(getUserTime(), Total.getUserTime(), OS);
 162   if (Total.getSystemTime())
 163     printVal(getSystemTime(), Total.getSystemTime(), OS);
 164   if (Total.getProcessTime())
 165     printVal(getProcessTime(), Total.getProcessTime(), OS);
 166   printVal(getWallTime(), Total.getWallTime(), OS);
 167
 168   OS << "  ";
 169
 170   if (Total.getMemUsed())
 171     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
 172 }
 173
 174
 175 //===----------------------------------------------------------------------===//
 176 //   NamedRegionTimer Implementation
 177 //===----------------------------------------------------------------------===//
 178
 179 namespace {
 180
 181 typedef StringMap<Timer> Name2TimerMap;
 182
 183 class Name2PairMap {
 184   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
 185 public:
 186   ~Name2PairMap() {
 187     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
 188          I = Map.begin(), E = Map.end(); I != E; ++I)
 189       delete I->second.first;
 190   }
 191
 192   Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
 193              StringRef GroupDescription) {
 194     sys::SmartScopedLock<true> L(*TimerLock);
 195
 196     std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
 197
 198     if (!GroupEntry.first)
 199       GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
 200
 201     Timer &T = GroupEntry.second[Name];
 202     if (!T.isInitialized())
 203       T.init(Name, Description, *GroupEntry.first);
 204     return T;
 205   }
 206 };
 207
 208 }
 209
 210 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
 211
 212 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
 213                                    StringRef GroupName,
 214                                    StringRef GroupDescription, bool Enabled)
 215   : TimeRegion(!Enabled ? nullptr
 216                  : &NamedGroupedTimers->get(Name, Description, GroupName,
 217                                             GroupDescription)) {}
 218
 219 //===----------------------------------------------------------------------===//
 220 //   TimerGroup Implementation
 221 //===----------------------------------------------------------------------===//
 222
 223 /// This is the global list of TimerGroups, maintained by the TimerGroup
 224 /// ctor/dtor and is protected by the TimerLock lock.
 225 static TimerGroup *TimerGroupList = nullptr;
 226
 227 TimerGroup::TimerGroup(StringRef Name, StringRef Description)
 228   : Name(Name.begin(), Name.end()),
 229     Description(Description.begin(), Description.end()) {
 230   // Add the group to TimerGroupList.
 231   sys::SmartScopedLock<true> L(*TimerLock);
 232   if (TimerGroupList)
 233     TimerGroupList->Prev = &Next;
 234   Next = TimerGroupList;
 235   Prev = &TimerGroupList;
 236   TimerGroupList = this;
 237 }
 238
 239 TimerGroup::TimerGroup(StringRef Name, StringRef Description,
 240                        const StringMap<TimeRecord> &Records)
 241     : TimerGroup(Name, Description) {
 242   TimersToPrint.reserve(Records.size());
 243   for (const auto &P : Records)
 244     TimersToPrint.emplace_back(P.getValue(), P.getKey(), P.getKey());
 245   assert(TimersToPrint.size() == Records.size() && "Size mismatch");
 246 }
 247
 248 TimerGroup::~TimerGroup() {
 249   // If the timer group is destroyed before the timers it owns, accumulate and
 250   // print the timing data.
 251   while (FirstTimer)
 252     removeTimer(*FirstTimer);
 253
 254   // Remove the group from the TimerGroupList.
 255   sys::SmartScopedLock<true> L(*TimerLock);
 256   *Prev = Next;
 257   if (Next)
 258     Next->Prev = Prev;
 259 }
 260
 261
 262 void TimerGroup::removeTimer(Timer &T) {
 263   sys::SmartScopedLock<true> L(*TimerLock);
 264
 265   // If the timer was started, move its data to TimersToPrint.
 266   if (T.hasTriggered())
 267     TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
 268
 269   T.TG = nullptr;
 270
 271   // Unlink the timer from our list.
 272   *T.Prev = T.Next;
 273   if (T.Next)
 274     T.Next->Prev = T.Prev;
 275
 276   // Print the report when all timers in this group are destroyed if some of
 277   // them were started.
 278   if (FirstTimer || TimersToPrint.empty())
 279     return;
 280
 281   std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
 282   PrintQueuedTimers(*OutStream);
 283 }
 284
 285 void TimerGroup::addTimer(Timer &T) {
 286   sys::SmartScopedLock<true> L(*TimerLock);
 287
 288   // Add the timer to our list.
 289   if (FirstTimer)
 290     FirstTimer->Prev = &T.Next;
 291   T.Next = FirstTimer;
 292   T.Prev = &FirstTimer;
 293   FirstTimer = &T;
 294 }
 295
 296 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
 297   // Sort the timers in descending order by amount of time taken.
 298   llvm::sort(TimersToPrint.begin(), TimersToPrint.end());
 299
 300   TimeRecord Total;
 301   for (const PrintRecord &Record : TimersToPrint)
 302     Total += Record.Time;
 303
 304   // Print out timing header.
 305   OS << "===" << std::string(73, '-') << "===\n";
 306   // Figure out how many spaces to indent TimerGroup name.
 307   unsigned Padding = (80-Description.length())/2;
 308   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
 309   OS.indent(Padding) << Description << '\n';
 310   OS << "===" << std::string(73, '-') << "===\n";
 311
 312   // If this is not an collection of ungrouped times, print the total time.
 313   // Ungrouped timers don't really make sense to add up.  We still print the
 314   // TOTAL line to make the percentages make sense.
 315   if (this != getDefaultTimerGroup())
 316     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
 317                  Total.getProcessTime(), Total.getWallTime());
 318   OS << '\n';
 319
 320   if (Total.getUserTime())
 321     OS << "   ---User Time---";
 322   if (Total.getSystemTime())
 323     OS << "   --System Time--";
 324   if (Total.getProcessTime())
 325     OS << "   --User+System--";
 326   OS << "   ---Wall Time---";
 327   if (Total.getMemUsed())
 328     OS << "  ---Mem---";
 329   OS << "  --- Name ---\n";
 330
 331   // Loop through all of the timing data, printing it out.
 332   for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
 333                                               TimersToPrint.rend())) {
 334     Record.Time.print(Total, OS);
 335     OS << Record.Description << '\n';
 336   }
 337
 338   Total.print(Total, OS);
 339   OS << "Total\n\n";
 340   OS.flush();
 341
 342   TimersToPrint.clear();
 343 }
 344
 345 void TimerGroup::prepareToPrintList() {
 346   // See if any of our timers were started, if so add them to TimersToPrint and
 347   // reset them.
 348   for (Timer *T = FirstTimer; T; T = T->Next) {
 349     if (!T->hasTriggered()) continue;
 350     bool WasRunning = T->isRunning();
 351     if (WasRunning)
 352       T->stopTimer();
 353
 354     TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
 355
 356     if (WasRunning)
 357       T->startTimer();
 358   }
 359 }
 360
 361 void TimerGroup::print(raw_ostream &OS) {
 362   sys::SmartScopedLock<true> L(*TimerLock);
 363
 364   prepareToPrintList();
 365
 366   // If any timers were started, print the group.
 367   if (!TimersToPrint.empty())
 368     PrintQueuedTimers(OS);
 369 }
 370
 371 void TimerGroup::printAll(raw_ostream &OS) {
 372   sys::SmartScopedLock<true> L(*TimerLock);
 373
 374   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
 375     TG->print(OS);
 376 }
 377
 378 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
 379                                 const char *suffix, double Value) {
 380   assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
 381          "TimerGroup name should not need quotes");
 382   assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
 383          "Timer name should not need quotes");
 384   constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
 385   OS << "\t\"time." << Name << '.' << R.Name << suffix
 386      << "\": " << format("%.*e", max_digits10 - 1, Value);
 387 }
 388
 389 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
 390   sys::SmartScopedLock<true> L(*TimerLock);
 391
 392   prepareToPrintList();
 393   for (const PrintRecord &R : TimersToPrint) {
 394     OS << delim;
 395     delim = ",\n";
 396
 397     const TimeRecord &T = R.Time;
 398     printJSONValue(OS, R, ".wall", T.getWallTime());
 399     OS << delim;
 400     printJSONValue(OS, R, ".user", T.getUserTime());
 401     OS << delim;
 402     printJSONValue(OS, R, ".sys", T.getSystemTime());
 403     if (T.getMemUsed()) {
 404       OS << delim;
 405       printJSONValue(OS, R, ".mem", T.getMemUsed());
 406     }
 407   }
 408   TimersToPrint.clear();
 409   return delim;
 410 }
 411
 412 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
 413   sys::SmartScopedLock<true> L(*TimerLock);
 414   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
 415     delim = TG->printJSONValues(OS, delim);
 416   return delim;
 417 }
 418
 419 void TimerGroup::ConstructTimerLists() {
 420   (void)*NamedGroupedTimers;
 421 }