LLVM API Documentation
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