LLVM API Documentation

Main Page | Namespace List | Class Hierarchy | Alphabetical List | Class List | Directories | File List | Namespace Members | Class Members | File Members | Related Pages

Timer.cpp

Go to the documentation of this file.
00001 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
00002 // 
00003 //                     The LLVM Compiler Infrastructure
00004 //
00005 // This file was developed by the LLVM research group and is distributed under
00006 // the University of Illinois Open Source License. See LICENSE.TXT for details.
00007 // 
00008 //===----------------------------------------------------------------------===//
00009 //
00010 // Interval Timing implementation.
00011 //
00012 //===----------------------------------------------------------------------===//
00013 
00014 #include "llvm/Support/Timer.h"
00015 #include "llvm/Support/CommandLine.h"
00016 #include <algorithm>
00017 #include <iostream>
00018 #include <functional>
00019 #include <fstream>
00020 #include <map>
00021 #include "llvm/Config/sys/resource.h"
00022 #include "llvm/Config/sys/time.h"
00023 #include "llvm/Config/unistd.h"
00024 #include "llvm/Config/malloc.h"
00025 #include "llvm/Config/windows.h"
00026 using namespace llvm;
00027 
00028 // GetLibSupportInfoOutputFile - Return a file stream to print our output on.
00029 namespace llvm { extern std::ostream *GetLibSupportInfoOutputFile(); }
00030 
00031 // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
00032 // of constructor/destructor ordering being unspecified by C++.  Basically the
00033 // problem is that a Statistic<> object gets destroyed, which ends up calling
00034 // 'GetLibSupportInfoOutputFile()' (below), which calls this function.
00035 // LibSupportInfoOutputFilename used to be a global variable, but sometimes it
00036 // would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
00037 // this by creating the string the first time it is needed and never destroying
00038 // it.
00039 static std::string &getLibSupportInfoOutputFilename() {
00040   static std::string *LibSupportInfoOutputFilename = new std::string();
00041   return *LibSupportInfoOutputFilename;
00042 }
00043 
00044 namespace {
00045 #ifdef HAVE_MALLINFO
00046   cl::opt<bool>
00047   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
00048                                       "tracking (this may be slow)"),
00049              cl::Hidden);
00050 #endif
00051 
00052   cl::opt<std::string, true>
00053   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
00054                      cl::desc("File to append -stats and -timer output to"),
00055                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
00056 }
00057 
00058 static TimerGroup *DefaultTimerGroup = 0;
00059 static TimerGroup *getDefaultTimerGroup() {
00060   if (DefaultTimerGroup) return DefaultTimerGroup;
00061   return DefaultTimerGroup = new TimerGroup("Miscellaneous Ungrouped Timers");
00062 }
00063 
00064 Timer::Timer(const std::string &N)
00065   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
00066     Started(false), TG(getDefaultTimerGroup()) {
00067   TG->addTimer();
00068 }
00069 
00070 Timer::Timer(const std::string &N, TimerGroup &tg)
00071   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
00072     Started(false), TG(&tg) {
00073   TG->addTimer();
00074 }
00075 
00076 Timer::Timer(const Timer &T) {
00077   TG = T.TG;
00078   if (TG) TG->addTimer();
00079   operator=(T);
00080 }
00081 
00082 
00083 // Copy ctor, initialize with no TG member.
00084 Timer::Timer(bool, const Timer &T) {
00085   TG = T.TG;     // Avoid assertion in operator=
00086   operator=(T);  // Copy contents
00087   TG = 0;
00088 }
00089 
00090 
00091 Timer::~Timer() {
00092   if (TG) {
00093     if (Started) {
00094       Started = false;
00095       TG->addTimerToPrint(*this);
00096     }
00097     TG->removeTimer();
00098   }
00099 }
00100 
00101 static long getMemUsage() {
00102 #ifdef HAVE_MALLINFO
00103   if (TrackSpace) {
00104     struct mallinfo MI = mallinfo();
00105     return MI.uordblks/*+MI.hblkhd*/;
00106   }
00107 #endif
00108   return 0;
00109 }
00110 
00111 struct TimeRecord {
00112   double Elapsed, UserTime, SystemTime;
00113   long MemUsed;
00114 };
00115 
00116 static TimeRecord getTimeRecord(bool Start) {
00117 #if defined(HAVE_WINDOWS_H)
00118   unsigned __int64 ProcCreate, ProcExit, KernelTime, UserTime, CurTime;
00119 
00120   GetProcessTimes(GetCurrentProcess(), (FILETIME*)&ProcCreate, 
00121                   (FILETIME*)&ProcExit, (FILETIME*)&KernelTime, 
00122                   (FILETIME*)&UserTime);
00123   GetSystemTimeAsFileTime((FILETIME*)&CurTime);
00124 
00125   // FILETIME's are # of 100 nanosecond ticks.
00126   double ScaleFactor = 1.0/(10*1000*1000);
00127 
00128   TimeRecord Result;
00129   Result.Elapsed    = (CurTime-ProcCreate)*ScaleFactor;  // Wall time
00130   Result.UserTime   = UserTime*ScaleFactor;
00131   Result.SystemTime = KernelTime*ScaleFactor;
00132   return Result;
00133 #elif defined(HAVE_GETRUSAGE)
00134   struct rusage RU;
00135   struct timeval T;
00136   long MemUsed = 0;
00137   if (Start) {
00138     MemUsed = getMemUsage();
00139     if (getrusage(RUSAGE_SELF, &RU))
00140       perror("getrusage call failed: -time-passes info incorrect!");
00141   }
00142   gettimeofday(&T, 0);
00143 
00144   if (!Start) {
00145     if (getrusage(RUSAGE_SELF, &RU))
00146       perror("getrusage call failed: -time-passes info incorrect!");
00147     MemUsed = getMemUsage();
00148   }
00149 
00150   TimeRecord Result;
00151   Result.Elapsed    =           T.tv_sec +           T.tv_usec/1000000.0;
00152   Result.UserTime   = RU.ru_utime.tv_sec + RU.ru_utime.tv_usec/1000000.0;
00153   Result.SystemTime = RU.ru_stime.tv_sec + RU.ru_stime.tv_usec/1000000.0;
00154   Result.MemUsed = MemUsed;
00155   return Result;
00156 #else
00157   // Can't get resource usage.
00158   return TimeRecord();
00159 #endif
00160 }
00161 
00162 static std::vector<Timer*> ActiveTimers;
00163 
00164 void Timer::startTimer() {
00165   Started = true;
00166   TimeRecord TR = getTimeRecord(true);
00167   Elapsed    -= TR.Elapsed;
00168   UserTime   -= TR.UserTime;
00169   SystemTime -= TR.SystemTime;
00170   MemUsed    -= TR.MemUsed;
00171   PeakMemBase = TR.MemUsed;
00172   ActiveTimers.push_back(this);
00173 }
00174 
00175 void Timer::stopTimer() {
00176   TimeRecord TR = getTimeRecord(false);
00177   Elapsed    += TR.Elapsed;
00178   UserTime   += TR.UserTime;
00179   SystemTime += TR.SystemTime;
00180   MemUsed    += TR.MemUsed;
00181 
00182   if (ActiveTimers.back() == this) {
00183     ActiveTimers.pop_back();
00184   } else {
00185     std::vector<Timer*>::iterator I =
00186       std::find(ActiveTimers.begin(), ActiveTimers.end(), this);
00187     assert(I != ActiveTimers.end() && "stop but no startTimer?");
00188     ActiveTimers.erase(I);
00189   }
00190 }
00191 
00192 void Timer::sum(const Timer &T) {
00193   Elapsed    += T.Elapsed;
00194   UserTime   += T.UserTime;
00195   SystemTime += T.SystemTime;
00196   MemUsed    += T.MemUsed;
00197   PeakMem    += T.PeakMem;
00198 }
00199 
00200 /// addPeakMemoryMeasurement - This method should be called whenever memory
00201 /// usage needs to be checked.  It adds a peak memory measurement to the
00202 /// currently active timers, which will be printed when the timer group prints
00203 ///
00204 void Timer::addPeakMemoryMeasurement() {
00205   long MemUsed = getMemUsage();
00206 
00207   for (std::vector<Timer*>::iterator I = ActiveTimers.begin(),
00208          E = ActiveTimers.end(); I != E; ++I)
00209     (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase);
00210 }
00211 
00212 //===----------------------------------------------------------------------===//
00213 //   NamedRegionTimer Implementation
00214 //===----------------------------------------------------------------------===//
00215 
00216 static Timer &getNamedRegionTimer(const std::string &Name) {
00217   static std::map<std::string, Timer> NamedTimers;
00218 
00219   std::map<std::string, Timer>::iterator I = NamedTimers.lower_bound(Name);
00220   if (I != NamedTimers.end() && I->first == Name)
00221     return I->second;
00222 
00223   return NamedTimers.insert(I, std::make_pair(Name, Timer(Name)))->second;
00224 }
00225 
00226 NamedRegionTimer::NamedRegionTimer(const std::string &Name)
00227   : TimeRegion(getNamedRegionTimer(Name)) {}
00228 
00229 
00230 //===----------------------------------------------------------------------===//
00231 //   TimerGroup Implementation
00232 //===----------------------------------------------------------------------===//
00233 
00234 // printAlignedFP - Simulate the printf "%A.Bf" format, where A is the
00235 // TotalWidth size, and B is the AfterDec size.
00236 //
00237 static void printAlignedFP(double Val, unsigned AfterDec, unsigned TotalWidth,
00238                            std::ostream &OS) {
00239   assert(TotalWidth >= AfterDec+1 && "Bad FP Format!");
00240   OS.width(TotalWidth-AfterDec-1);
00241   char OldFill = OS.fill();
00242   OS.fill(' ');
00243   OS << (int)Val;  // Integer part;
00244   OS << ".";
00245   OS.width(AfterDec);
00246   OS.fill('0');
00247   unsigned ResultFieldSize = 1;
00248   while (AfterDec--) ResultFieldSize *= 10;
00249   OS << (int)(Val*ResultFieldSize) % ResultFieldSize;
00250   OS.fill(OldFill);
00251 }
00252 
00253 static void printVal(double Val, double Total, std::ostream &OS) {
00254   if (Total < 1e-7)   // Avoid dividing by zero...
00255     OS << "        -----     ";
00256   else {
00257     OS << "  ";
00258     printAlignedFP(Val, 4, 7, OS);
00259     OS << " (";
00260     printAlignedFP(Val*100/Total, 1, 5, OS);
00261     OS << "%)";
00262   }
00263 }
00264 
00265 void Timer::print(const Timer &Total, std::ostream &OS) {
00266   if (Total.UserTime)
00267     printVal(UserTime, Total.UserTime, OS);
00268   if (Total.SystemTime)
00269     printVal(SystemTime, Total.SystemTime, OS);
00270   if (Total.getProcessTime())
00271     printVal(getProcessTime(), Total.getProcessTime(), OS);
00272   printVal(Elapsed, Total.Elapsed, OS);
00273   
00274   OS << "  ";
00275 
00276   if (Total.MemUsed) {
00277     OS.width(9);
00278     OS << MemUsed << "  ";
00279   }
00280   if (Total.PeakMem) {
00281     if (PeakMem) {
00282       OS.width(9);
00283       OS << PeakMem << "  ";
00284     } else
00285       OS << "           ";
00286   }
00287   OS << Name << "\n";
00288 
00289   Started = false;  // Once printed, don't print again
00290 }
00291 
00292 // GetLibSupportInfoOutputFile - Return a file stream to print our output on...
00293 std::ostream *
00294 llvm::GetLibSupportInfoOutputFile() {
00295   std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename();
00296   if (LibSupportInfoOutputFilename.empty())
00297     return &std::cerr;
00298   if (LibSupportInfoOutputFilename == "-")
00299     return &std::cout;
00300 
00301   std::ostream *Result = new std::ofstream(LibSupportInfoOutputFilename.c_str(),
00302                                            std::ios::app);
00303   if (!Result->good()) {
00304     std::cerr << "Error opening info-output-file '"
00305               << LibSupportInfoOutputFilename << " for appending!\n";
00306     delete Result;
00307     return &std::cerr;
00308   }
00309   return Result;
00310 }
00311 
00312 
00313 void TimerGroup::removeTimer() {
00314   if (--NumTimers == 0 && !TimersToPrint.empty()) { // Print timing report...
00315     // Sort the timers in descending order by amount of time taken...
00316     std::sort(TimersToPrint.begin(), TimersToPrint.end(),
00317               std::greater<Timer>());
00318 
00319     // Figure out how many spaces to indent TimerGroup name...
00320     unsigned Padding = (80-Name.length())/2;
00321     if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
00322 
00323     std::ostream *OutStream = GetLibSupportInfoOutputFile();
00324 
00325     ++NumTimers;
00326     {  // Scope to contain Total timer... don't allow total timer to drop us to
00327        // zero timers...
00328       Timer Total("TOTAL");
00329   
00330       for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
00331         Total.sum(TimersToPrint[i]);
00332       
00333       // Print out timing header...
00334       *OutStream << "===" << std::string(73, '-') << "===\n"
00335                  << std::string(Padding, ' ') << Name << "\n"
00336                  << "===" << std::string(73, '-')
00337                  << "===\n  Total Execution Time: ";
00338 
00339       printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream);
00340       *OutStream << " seconds (";
00341       printAlignedFP(Total.getWallTime(), 4, 5, *OutStream);
00342       *OutStream << " wall clock)\n\n";
00343 
00344       if (Total.UserTime)
00345         *OutStream << "   ---User Time---";
00346       if (Total.SystemTime)
00347         *OutStream << "   --System Time--";
00348       if (Total.getProcessTime())
00349         *OutStream << "   --User+System--";
00350       *OutStream << "   ---Wall Time---";
00351       if (Total.getMemUsed())
00352         *OutStream << "  ---Mem---";
00353       if (Total.getPeakMem())
00354         *OutStream << "  -PeakMem-";
00355       *OutStream << "  --- Name ---\n";
00356       
00357       // Loop through all of the timing data, printing it out...
00358       for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
00359         TimersToPrint[i].print(Total, *OutStream);
00360     
00361       Total.print(Total, *OutStream);
00362       *OutStream << std::endl;  // Flush output
00363     }
00364     --NumTimers;
00365 
00366     TimersToPrint.clear();
00367 
00368     if (OutStream != &std::cerr && OutStream != &std::cout)
00369       delete OutStream;   // Close the file...
00370   }
00371 
00372   // Delete default timer group!
00373   if (NumTimers == 0 && this == DefaultTimerGroup) {
00374     delete DefaultTimerGroup;
00375     DefaultTimerGroup = 0;
00376   }
00377 }
00378