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