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