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 // Interval Timing implementation.
  11 //
  12 //===----------------------------------------------------------------------===//
  13
  14 #include "llvm/Support/Timer.h"
  15 #include "llvm/Support/CommandLine.h"
  16 #include "llvm/Support/Debug.h"
  17 #include "llvm/Support/ManagedStatic.h"
  18 #include "llvm/Support/raw_ostream.h"
  19 #include "llvm/Support/Format.h"
  20 #include "llvm/System/Mutex.h"
  21 #include "llvm/System/Process.h"
  22 #include <map>
  23 using namespace llvm;
  24
  25 // GetLibSupportInfoOutputFile - Return a file stream to print our output on.
  26 namespace llvm { extern raw_ostream *GetLibSupportInfoOutputFile(); }
  27
  28 // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
  29 // of constructor/destructor ordering being unspecified by C++.  Basically the
  30 // problem is that a Statistic object gets destroyed, which ends up calling
  31 // 'GetLibSupportInfoOutputFile()' (below), which calls this function.
  32 // LibSupportInfoOutputFilename used to be a global variable, but sometimes it
  33 // would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
  34 // this by creating the string the first time it is needed and never destroying
  35 // 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 // GetLibSupportInfoOutputFile - Return a file stream to print our output on.
  56 raw_ostream *llvm::GetLibSupportInfoOutputFile() {
  57   std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename();
  58   if (LibSupportInfoOutputFilename.empty())
  59     return &errs();
  60   if (LibSupportInfoOutputFilename == "-")
  61     return &outs();
  62
  63   std::string Error;
  64   raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(),
  65                                            Error, raw_fd_ostream::F_Append);
  66   if (Error.empty())
  67     return Result;
  68
  69   errs() << "Error opening info-output-file '"
  70     << LibSupportInfoOutputFilename << " for appending!\n";
  71   delete Result;
  72   return &errs();
  73 }
  74
  75
  76 static TimerGroup *DefaultTimerGroup = 0;
  77 static TimerGroup *getDefaultTimerGroup() {
  78   TimerGroup *tmp = DefaultTimerGroup;
  79   sys::MemoryFence();
  80   if (tmp) return tmp;
  81
  82   llvm_acquire_global_lock();
  83   tmp = DefaultTimerGroup;
  84   if (!tmp) {
  85     tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
  86     sys::MemoryFence();
  87     DefaultTimerGroup = tmp;
  88   }
  89   llvm_release_global_lock();
  90
  91   return tmp;
  92 }
  93
  94 //===----------------------------------------------------------------------===//
  95 // Timer Implementation
  96 //===----------------------------------------------------------------------===//
  97
  98 Timer::Timer(const std::string &N)
  99   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), Name(N),
 100     Started(false), TG(getDefaultTimerGroup()) {
 101   TG->addTimer();
 102 }
 103
 104 Timer::Timer(const std::string &N, TimerGroup &tg)
 105   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), Name(N),
 106     Started(false), TG(&tg) {
 107   TG->addTimer();
 108 }
 109
 110 Timer::Timer(const Timer &T) {
 111   TG = T.TG;
 112   if (TG) TG->addTimer();
 113   operator=(T);
 114 }
 115
 116 // Copy ctor, initialize with no TG member.
 117 Timer::Timer(bool, const Timer &T) {
 118   TG = T.TG;     // Avoid assertion in operator=
 119   operator=(T);  // Copy contents
 120   TG = 0;
 121 }
 122
 123 Timer::~Timer() {
 124   if (!TG) return;
 125
 126   if (Started) {
 127     Started = false;
 128     TG->addTimerToPrint(*this);
 129   }
 130   TG->removeTimer();
 131 }
 132
 133 static inline size_t getMemUsage() {
 134   if (TrackSpace)
 135     return sys::Process::GetMallocUsage();
 136   return 0;
 137 }
 138
 139 struct TimeRecord {
 140   double Elapsed, UserTime, SystemTime;
 141   ssize_t MemUsed;
 142 };
 143
 144 static TimeRecord getTimeRecord(bool Start) {
 145   TimeRecord Result;
 146
 147   sys::TimeValue now(0,0);
 148   sys::TimeValue user(0,0);
 149   sys::TimeValue sys(0,0);
 150
 151   ssize_t MemUsed = 0;
 152   if (Start) {
 153     MemUsed = getMemUsage();
 154     sys::Process::GetTimeUsage(now, user, sys);
 155   } else {
 156     sys::Process::GetTimeUsage(now, user, sys);
 157     MemUsed = getMemUsage();
 158   }
 159
 160   Result.Elapsed    =  now.seconds()  + now.microseconds() / 1000000.0;
 161   Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
 162   Result.SystemTime =  sys.seconds()  + sys.microseconds() / 1000000.0;
 163   Result.MemUsed = MemUsed;
 164   return Result;
 165 }
 166
 167 static ManagedStatic<std::vector<Timer*> > ActiveTimers;
 168
 169 void Timer::startTimer() {
 170   Started = true;
 171   ActiveTimers->push_back(this);
 172   TimeRecord TR = getTimeRecord(true);
 173   Elapsed    -= TR.Elapsed;
 174   UserTime   -= TR.UserTime;
 175   SystemTime -= TR.SystemTime;
 176   MemUsed    -= TR.MemUsed;
 177 }
 178
 179 void Timer::stopTimer() {
 180   TimeRecord TR = getTimeRecord(false);
 181   Elapsed    += TR.Elapsed;
 182   UserTime   += TR.UserTime;
 183   SystemTime += TR.SystemTime;
 184   MemUsed    += TR.MemUsed;
 185
 186   if (ActiveTimers->back() == this) {
 187     ActiveTimers->pop_back();
 188   } else {
 189     std::vector<Timer*>::iterator I =
 190       std::find(ActiveTimers->begin(), ActiveTimers->end(), this);
 191     assert(I != ActiveTimers->end() && "stop but no startTimer?");
 192     ActiveTimers->erase(I);
 193   }
 194 }
 195
 196 void Timer::sum(const Timer &T) {
 197   Elapsed    += T.Elapsed;
 198   UserTime   += T.UserTime;
 199   SystemTime += T.SystemTime;
 200   MemUsed    += T.MemUsed;
 201 }
 202
 203 const Timer &Timer::operator=(const Timer &T) {
 204   Elapsed = T.Elapsed;
 205   UserTime = T.UserTime;
 206   SystemTime = T.SystemTime;
 207   MemUsed = T.MemUsed;
 208   Name = T.Name;
 209   Started = T.Started;
 210   assert(TG == T.TG && "Can only assign timers in the same TimerGroup!");
 211   return *this;
 212 }
 213
 214
 215 static void printVal(double Val, double Total, raw_ostream &OS) {
 216   if (Total < 1e-7)   // Avoid dividing by zero.
 217     OS << "        -----     ";
 218   else {
 219     OS << "  " << format("%7.4f", Val) << " (";
 220     OS << format("%5.1f", Val*100/Total) << "%)";
 221   }
 222 }
 223
 224 void Timer::print(const Timer &Total, raw_ostream &OS) {
 225   if (Total.UserTime)
 226     printVal(UserTime, Total.UserTime, OS);
 227   if (Total.SystemTime)
 228     printVal(SystemTime, Total.SystemTime, OS);
 229   if (Total.getProcessTime())
 230     printVal(getProcessTime(), Total.getProcessTime(), OS);
 231   printVal(Elapsed, Total.Elapsed, OS);
 232
 233   OS << "  ";
 234
 235   if (Total.MemUsed)
 236     OS << format("%9lld", (long long)MemUsed) << "  ";
 237
 238   OS << Name << "\n";
 239
 240   Started = false;  // Once printed, don't print again
 241 }
 242
 243
 244 //===----------------------------------------------------------------------===//
 245 //   NamedRegionTimer Implementation
 246 //===----------------------------------------------------------------------===//
 247
 248 typedef std::map<std::string, Timer> Name2Timer;
 249 typedef std::map<std::string, std::pair<TimerGroup, Name2Timer> > Name2Pair;
 250
 251 static ManagedStatic<Name2Timer> NamedTimers;
 252 static ManagedStatic<Name2Pair> NamedGroupedTimers;
 253
 254 static Timer &getNamedRegionTimer(const std::string &Name) {
 255   sys::SmartScopedLock<true> L(*TimerLock);
 256   Name2Timer::iterator I = NamedTimers->find(Name);
 257   if (I != NamedTimers->end())
 258     return I->second;
 259
 260   return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second;
 261 }
 262
 263 static Timer &getNamedRegionTimer(const std::string &Name,
 264                                   const std::string &GroupName) {
 265   sys::SmartScopedLock<true> L(*TimerLock);
 266
 267   Name2Pair::iterator I = NamedGroupedTimers->find(GroupName);
 268   if (I == NamedGroupedTimers->end()) {
 269     TimerGroup TG(GroupName);
 270     std::pair<TimerGroup, Name2Timer> Pair(TG, Name2Timer());
 271     I = NamedGroupedTimers->insert(I, std::make_pair(GroupName, Pair));
 272   }
 273
 274   Name2Timer::iterator J = I->second.second.find(Name);
 275   if (J == I->second.second.end())
 276     J = I->second.second.insert(J,
 277                                 std::make_pair(Name,
 278                                                Timer(Name,
 279                                                      I->second.first)));
 280
 281   return J->second;
 282 }
 283
 284 NamedRegionTimer::NamedRegionTimer(const std::string &Name)
 285   : TimeRegion(getNamedRegionTimer(Name)) {}
 286
 287 NamedRegionTimer::NamedRegionTimer(const std::string &Name,
 288                                    const std::string &GroupName)
 289   : TimeRegion(getNamedRegionTimer(Name, GroupName)) {}
 290
 291 //===----------------------------------------------------------------------===//
 292 //   TimerGroup Implementation
 293 //===----------------------------------------------------------------------===//
 294
 295 void TimerGroup::removeTimer() {
 296   sys::SmartScopedLock<true> L(*TimerLock);
 297   if (--NumTimers != 0 || TimersToPrint.empty())
 298     return; // Don't print timing report.
 299
 300   // Sort the timers in descending order by amount of time taken.
 301   std::sort(TimersToPrint.begin(), TimersToPrint.end(),
 302             std::greater<Timer>());
 303
 304   // Figure out how many spaces to indent TimerGroup name.
 305   unsigned Padding = (80-Name.length())/2;
 306   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
 307
 308   raw_ostream *OutStream = GetLibSupportInfoOutputFile();
 309
 310   ++NumTimers;
 311   {  // Scope to contain Total timer: don't allow total timer to drop us to
 312      // zero timers.
 313     Timer Total("TOTAL");
 314
 315     for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
 316       Total.sum(TimersToPrint[i]);
 317
 318     // Print out timing header.
 319     *OutStream << "===" << std::string(73, '-') << "===\n"
 320                << std::string(Padding, ' ') << Name << "\n"
 321                << "===" << std::string(73, '-')
 322                << "===\n";
 323
 324     // If this is not an collection of ungrouped times, print the total time.
 325     // Ungrouped timers don't really make sense to add up.  We still print the
 326     // TOTAL line to make the percentages make sense.
 327     if (this != DefaultTimerGroup) {
 328       *OutStream << "  Total Execution Time: ";
 329       *OutStream << format("%5.4f", Total.getProcessTime()) << " seconds (";
 330       *OutStream << format("%5.4f", Total.getWallTime()) << " wall clock)\n";
 331     }
 332     *OutStream << "\n";
 333
 334     if (Total.UserTime)
 335       *OutStream << "   ---User Time---";
 336     if (Total.SystemTime)
 337       *OutStream << "   --System Time--";
 338     if (Total.getProcessTime())
 339       *OutStream << "   --User+System--";
 340     *OutStream << "   ---Wall Time---";
 341     if (Total.getMemUsed())
 342       *OutStream << "  ---Mem---";
 343     *OutStream << "  --- Name ---\n";
 344
 345     // Loop through all of the timing data, printing it out.
 346     for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
 347       TimersToPrint[i].print(Total, *OutStream);
 348
 349     Total.print(Total, *OutStream);
 350     *OutStream << '\n';
 351     OutStream->flush();
 352   }
 353   --NumTimers;
 354
 355   TimersToPrint.clear();
 356
 357   if (OutStream != &errs() && OutStream != &outs())
 358     delete OutStream;   // Close the file.
 359 }
 360
 361 void TimerGroup::addTimer() {
 362   sys::SmartScopedLock<true> L(*TimerLock);
 363   ++NumTimers;
 364 }
 365
 366 void TimerGroup::addTimerToPrint(const Timer &T) {
 367   sys::SmartScopedLock<true> L(*TimerLock);
 368   TimersToPrint.push_back(Timer(true, T));
 369 }
 370