lib/Support/Timer.cpp

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