Timer.cpp revision d5a310e4b3251410d4afd58ccea5ec7f0cb13d5f
1//===-- Timer.cpp - Interval Timing Support -------------------------------===// 2// 3// Interval Timing implementation. 4// 5//===----------------------------------------------------------------------===// 6 7#include "Support/Timer.h" 8#include "Support/CommandLine.h" 9 10#include "Config/sys/resource.h" 11#include "Config/sys/time.h" 12#include "Config/unistd.h" 13#include "Config/malloc.h" 14#include "Config/stdio.h" 15#include <iostream> 16#include <algorithm> 17#include <functional> 18#include <fstream> 19#include <map> 20 21// getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy 22// of constructor/destructor ordering being unspecified by C++. Basically the 23// problem is that a Statistic<> object gets destroyed, which ends up calling 24// 'GetLibSupportInfoOutputFile()' (below), which calls this function. 25// LibSupportInfoOutputFilename used to be a global variable, but sometimes it 26// would get destroyed before the Statistic, causing havoc to ensue. We "fix" 27// this by creating the string the first time it is needed and never destroying 28// it. 29static std::string &getLibSupportInfoOutputFilename() { 30 static std::string *LibSupportInfoOutputFilename = new std::string(); 31 return *LibSupportInfoOutputFilename; 32} 33 34namespace { 35#ifdef HAVE_MALLINFO 36 cl::opt<bool> 37 TrackSpace("track-memory", cl::desc("Enable -time-passes memory " 38 "tracking (this may be slow)"), 39 cl::Hidden); 40#endif 41 42 cl::opt<std::string, true> 43 InfoOutputFilename("info-output-file", cl::value_desc("filename"), 44 cl::desc("File to append -stats and -timer output to"), 45 cl::Hidden, cl::location(getLibSupportInfoOutputFilename())); 46} 47 48static TimerGroup *DefaultTimerGroup = 0; 49static TimerGroup *getDefaultTimerGroup() { 50 if (DefaultTimerGroup) return DefaultTimerGroup; 51 return DefaultTimerGroup = new TimerGroup("Miscellaneous Ungrouped Timers"); 52} 53 54Timer::Timer(const std::string &N) 55 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 56 Started(false), TG(getDefaultTimerGroup()) { 57 TG->addTimer(); 58} 59 60Timer::Timer(const std::string &N, TimerGroup &tg) 61 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 62 Started(false), TG(&tg) { 63 TG->addTimer(); 64} 65 66Timer::Timer(const Timer &T) { 67 TG = T.TG; 68 if (TG) TG->addTimer(); 69 operator=(T); 70} 71 72 73// Copy ctor, initialize with no TG member. 74Timer::Timer(bool, const Timer &T) { 75 TG = T.TG; // Avoid assertion in operator= 76 operator=(T); // Copy contents 77 TG = 0; 78} 79 80 81Timer::~Timer() { 82 if (TG) { 83 if (Started) { 84 Started = false; 85 TG->addTimerToPrint(*this); 86 } 87 TG->removeTimer(); 88 } 89} 90 91static long getMemUsage() { 92#ifdef HAVE_MALLINFO 93 if (TrackSpace) { 94 struct mallinfo MI = mallinfo(); 95 return MI.uordblks/*+MI.hblkhd*/; 96 } 97#endif 98 return 0; 99} 100 101struct TimeRecord { 102 double Elapsed, UserTime, SystemTime; 103 long MemUsed; 104}; 105 106static TimeRecord getTimeRecord(bool Start) { 107 struct rusage RU; 108 struct timeval T; 109 long MemUsed = 0; 110 if (Start) { 111 MemUsed = getMemUsage(); 112 if (getrusage(RUSAGE_SELF, &RU)) 113 perror("getrusage call failed: -time-passes info incorrect!"); 114 } 115 gettimeofday(&T, 0); 116 117 if (!Start) { 118 MemUsed = getMemUsage(); 119 if (getrusage(RUSAGE_SELF, &RU)) 120 perror("getrusage call failed: -time-passes info incorrect!"); 121 } 122 123 TimeRecord Result; 124 Result.Elapsed = T.tv_sec + T.tv_usec/1000000.0; 125 Result.UserTime = RU.ru_utime.tv_sec + RU.ru_utime.tv_usec/1000000.0; 126 Result.SystemTime = RU.ru_stime.tv_sec + RU.ru_stime.tv_usec/1000000.0; 127 Result.MemUsed = MemUsed; 128 129 return Result; 130} 131 132static std::vector<Timer*> ActiveTimers; 133 134void Timer::startTimer() { 135 Started = true; 136 TimeRecord TR = getTimeRecord(true); 137 Elapsed -= TR.Elapsed; 138 UserTime -= TR.UserTime; 139 SystemTime -= TR.SystemTime; 140 MemUsed -= TR.MemUsed; 141 PeakMemBase = TR.MemUsed; 142 ActiveTimers.push_back(this); 143} 144 145void Timer::stopTimer() { 146 TimeRecord TR = getTimeRecord(false); 147 Elapsed += TR.Elapsed; 148 UserTime += TR.UserTime; 149 SystemTime += TR.SystemTime; 150 MemUsed += TR.MemUsed; 151 152 if (ActiveTimers.back() == this) { 153 ActiveTimers.pop_back(); 154 } else { 155 std::vector<Timer*>::iterator I = 156 std::find(ActiveTimers.begin(), ActiveTimers.end(), this); 157 assert(I != ActiveTimers.end() && "stop but no startTimer?"); 158 ActiveTimers.erase(I); 159 } 160} 161 162void Timer::sum(const Timer &T) { 163 Elapsed += T.Elapsed; 164 UserTime += T.UserTime; 165 SystemTime += T.SystemTime; 166 MemUsed += T.MemUsed; 167 PeakMem += T.PeakMem; 168} 169 170/// addPeakMemoryMeasurement - This method should be called whenever memory 171/// usage needs to be checked. It adds a peak memory measurement to the 172/// currently active timers, which will be printed when the timer group prints 173/// 174void Timer::addPeakMemoryMeasurement() { 175 long MemUsed = getMemUsage(); 176 177 for (std::vector<Timer*>::iterator I = ActiveTimers.begin(), 178 E = ActiveTimers.end(); I != E; ++I) 179 (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase); 180} 181 182//===----------------------------------------------------------------------===// 183// NamedRegionTimer Implementation 184//===----------------------------------------------------------------------===// 185 186static Timer &getNamedRegionTimer(const std::string &Name) { 187 static std::map<std::string, Timer> NamedTimers; 188 189 std::map<std::string, Timer>::iterator I = NamedTimers.lower_bound(Name); 190 if (I != NamedTimers.end() && I->first == Name) 191 return I->second; 192 193 return NamedTimers.insert(I, std::make_pair(Name, Timer(Name)))->second; 194} 195 196NamedRegionTimer::NamedRegionTimer(const std::string &Name) 197 : TimeRegion(getNamedRegionTimer(Name)) {} 198 199 200//===----------------------------------------------------------------------===// 201// TimerGroup Implementation 202//===----------------------------------------------------------------------===// 203 204// printAlignedFP - Simulate the printf "%A.Bf" format, where A is the 205// TotalWidth size, and B is the AfterDec size. 206// 207static void printAlignedFP(double Val, unsigned AfterDec, unsigned TotalWidth, 208 std::ostream &OS) { 209 assert(TotalWidth >= AfterDec+1 && "Bad FP Format!"); 210 OS.width(TotalWidth-AfterDec-1); 211 char OldFill = OS.fill(); 212 OS.fill(' '); 213 OS << (int)Val; // Integer part; 214 OS << "."; 215 OS.width(AfterDec); 216 OS.fill('0'); 217 unsigned ResultFieldSize = 1; 218 while (AfterDec--) ResultFieldSize *= 10; 219 OS << (int)(Val*ResultFieldSize) % ResultFieldSize; 220 OS.fill(OldFill); 221} 222 223static void printVal(double Val, double Total, std::ostream &OS) { 224 if (Total < 1e-7) // Avoid dividing by zero... 225 OS << " ----- "; 226 else { 227 OS << " "; 228 printAlignedFP(Val, 4, 7, OS); 229 OS << " ("; 230 printAlignedFP(Val*100/Total, 1, 5, OS); 231 OS << "%)"; 232 } 233} 234 235void Timer::print(const Timer &Total, std::ostream &OS) { 236 if (Total.UserTime) 237 printVal(UserTime, Total.UserTime, OS); 238 if (Total.SystemTime) 239 printVal(SystemTime, Total.SystemTime, OS); 240 if (Total.getProcessTime()) 241 printVal(getProcessTime(), Total.getProcessTime(), OS); 242 printVal(Elapsed, Total.Elapsed, OS); 243 244 OS << " "; 245 246 if (Total.MemUsed) { 247 OS.width(9); 248 OS << MemUsed << " "; 249 } 250 if (Total.PeakMem) { 251 if (PeakMem) { 252 OS.width(9); 253 OS << PeakMem << " "; 254 } else 255 OS << " "; 256 } 257 OS << Name << "\n"; 258 259 Started = false; // Once printed, don't print again 260} 261 262// GetLibSupportInfoOutputFile - Return a file stream to print our output on... 263std::ostream *GetLibSupportInfoOutputFile() { 264 std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename(); 265 if (LibSupportInfoOutputFilename.empty()) 266 return &std::cerr; 267 if (LibSupportInfoOutputFilename == "-") 268 return &std::cout; 269 270 std::ostream *Result = new std::ofstream(LibSupportInfoOutputFilename.c_str(), 271 std::ios::app); 272 if (!Result->good()) { 273 std::cerr << "Error opening info-output-file '" 274 << LibSupportInfoOutputFilename << " for appending!\n"; 275 delete Result; 276 return &std::cerr; 277 } 278 return Result; 279} 280 281 282void TimerGroup::removeTimer() { 283 if (--NumTimers == 0 && !TimersToPrint.empty()) { // Print timing report... 284 // Sort the timers in descending order by amount of time taken... 285 std::sort(TimersToPrint.begin(), TimersToPrint.end(), 286 std::greater<Timer>()); 287 288 // Figure out how many spaces to indent TimerGroup name... 289 unsigned Padding = (80-Name.length())/2; 290 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers 291 292 std::ostream *OutStream = GetLibSupportInfoOutputFile(); 293 294 ++NumTimers; 295 { // Scope to contain Total timer... don't allow total timer to drop us to 296 // zero timers... 297 Timer Total("TOTAL"); 298 299 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 300 Total.sum(TimersToPrint[i]); 301 302 // Print out timing header... 303 *OutStream << "===" << std::string(73, '-') << "===\n" 304 << std::string(Padding, ' ') << Name << "\n" 305 << "===" << std::string(73, '-') 306 << "===\n Total Execution Time: "; 307 308 printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream); 309 *OutStream << " seconds ("; 310 printAlignedFP(Total.getWallTime(), 4, 5, *OutStream); 311 *OutStream << " wall clock)\n\n"; 312 313 if (Total.UserTime) 314 *OutStream << " ---User Time---"; 315 if (Total.SystemTime) 316 *OutStream << " --System Time--"; 317 if (Total.getProcessTime()) 318 *OutStream << " --User+System--"; 319 *OutStream << " ---Wall Time---"; 320 if (Total.getMemUsed()) 321 *OutStream << " ---Mem---"; 322 if (Total.getPeakMem()) 323 *OutStream << " -PeakMem-"; 324 *OutStream << " --- Name ---\n"; 325 326 // Loop through all of the timing data, printing it out... 327 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 328 TimersToPrint[i].print(Total, *OutStream); 329 330 Total.print(Total, *OutStream); 331 *OutStream << std::endl; // Flush output 332 } 333 --NumTimers; 334 335 TimersToPrint.clear(); 336 337 if (OutStream != &std::cerr && OutStream != &std::cout) 338 delete OutStream; // Close the file... 339 } 340 341 // Delete default timer group! 342 if (NumTimers == 0 && this == DefaultTimerGroup) { 343 delete DefaultTimerGroup; 344 DefaultTimerGroup = 0; 345 } 346} 347