Timer.cpp revision 90aa839c88776e3dd0b3a798a98ea30d85b6b53c
1//===-- Timer.cpp - Interval Timing Support -------------------------------===// 2// 3// The LLVM Compiler Infrastructure 4// 5// This file was developed by the LLVM research group and is distributed under 6// the University of Illinois Open Source 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/ManagedStatic.h" 17#include "llvm/System/Process.h" 18#include <algorithm> 19#include <fstream> 20#include <functional> 21#include <iostream> 22#include <map> 23using namespace llvm; 24 25// GetLibSupportInfoOutputFile - Return a file stream to print our output on. 26namespace llvm { extern std::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. 36static ManagedStatic<std::string> LibSupportInfoOutputFilename; 37static std::string &getLibSupportInfoOutputFilename() { 38 return *LibSupportInfoOutputFilename; 39} 40 41namespace { 42 cl::opt<bool> 43 TrackSpace("track-memory", cl::desc("Enable -time-passes memory " 44 "tracking (this may be slow)"), 45 cl::Hidden); 46 47 cl::opt<std::string, true> 48 InfoOutputFilename("info-output-file", cl::value_desc("filename"), 49 cl::desc("File to append -stats and -timer output to"), 50 cl::Hidden, cl::location(getLibSupportInfoOutputFilename())); 51} 52 53static TimerGroup *DefaultTimerGroup = 0; 54static TimerGroup *getDefaultTimerGroup() { 55 if (DefaultTimerGroup) return DefaultTimerGroup; 56 return DefaultTimerGroup = new TimerGroup("Miscellaneous Ungrouped Timers"); 57} 58 59Timer::Timer(const std::string &N) 60 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 61 Started(false), TG(getDefaultTimerGroup()) { 62 TG->addTimer(); 63} 64 65Timer::Timer(const std::string &N, TimerGroup &tg) 66 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 67 Started(false), TG(&tg) { 68 TG->addTimer(); 69} 70 71Timer::Timer(const Timer &T) { 72 TG = T.TG; 73 if (TG) TG->addTimer(); 74 operator=(T); 75} 76 77 78// Copy ctor, initialize with no TG member. 79Timer::Timer(bool, const Timer &T) { 80 TG = T.TG; // Avoid assertion in operator= 81 operator=(T); // Copy contents 82 TG = 0; 83} 84 85 86Timer::~Timer() { 87 if (TG) { 88 if (Started) { 89 Started = false; 90 TG->addTimerToPrint(*this); 91 } 92 TG->removeTimer(); 93 } 94} 95 96static inline size_t getMemUsage() { 97 if (TrackSpace) 98 return sys::Process::GetMallocUsage(); 99 return 0; 100} 101 102struct TimeRecord { 103 double Elapsed, UserTime, SystemTime; 104 ssize_t MemUsed; 105}; 106 107static TimeRecord getTimeRecord(bool Start) { 108 TimeRecord Result; 109 110 sys::TimeValue now(0,0); 111 sys::TimeValue user(0,0); 112 sys::TimeValue sys(0,0); 113 114 ssize_t MemUsed = 0; 115 if (Start) { 116 MemUsed = getMemUsage(); 117 sys::Process::GetTimeUsage(now,user,sys); 118 } else { 119 sys::Process::GetTimeUsage(now,user,sys); 120 MemUsed = getMemUsage(); 121 } 122 123 Result.Elapsed = now.seconds() + now.microseconds() / 1000000.0; 124 Result.UserTime = user.seconds() + user.microseconds() / 1000000.0; 125 Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0; 126 Result.MemUsed = MemUsed; 127 128 return Result; 129} 130 131static ManagedStatic<std::vector<Timer*> > ActiveTimers; 132 133void Timer::startTimer() { 134 Started = true; 135 TimeRecord TR = getTimeRecord(true); 136 Elapsed -= TR.Elapsed; 137 UserTime -= TR.UserTime; 138 SystemTime -= TR.SystemTime; 139 MemUsed -= TR.MemUsed; 140 PeakMemBase = TR.MemUsed; 141 ActiveTimers->push_back(this); 142} 143 144void Timer::stopTimer() { 145 TimeRecord TR = getTimeRecord(false); 146 Elapsed += TR.Elapsed; 147 UserTime += TR.UserTime; 148 SystemTime += TR.SystemTime; 149 MemUsed += TR.MemUsed; 150 151 if (ActiveTimers->back() == this) { 152 ActiveTimers->pop_back(); 153 } else { 154 std::vector<Timer*>::iterator I = 155 std::find(ActiveTimers->begin(), ActiveTimers->end(), this); 156 assert(I != ActiveTimers->end() && "stop but no startTimer?"); 157 ActiveTimers->erase(I); 158 } 159} 160 161void Timer::sum(const Timer &T) { 162 Elapsed += T.Elapsed; 163 UserTime += T.UserTime; 164 SystemTime += T.SystemTime; 165 MemUsed += T.MemUsed; 166 PeakMem += T.PeakMem; 167} 168 169/// addPeakMemoryMeasurement - This method should be called whenever memory 170/// usage needs to be checked. It adds a peak memory measurement to the 171/// currently active timers, which will be printed when the timer group prints 172/// 173void Timer::addPeakMemoryMeasurement() { 174 size_t MemUsed = getMemUsage(); 175 176 for (std::vector<Timer*>::iterator I = ActiveTimers->begin(), 177 E = ActiveTimers->end(); I != E; ++I) 178 (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase); 179} 180 181//===----------------------------------------------------------------------===// 182// NamedRegionTimer Implementation 183//===----------------------------------------------------------------------===// 184 185static ManagedStatic<std::map<std::string, Timer> > NamedTimers; 186 187static Timer &getNamedRegionTimer(const std::string &Name) { 188 std::map<std::string, Timer>::iterator I = NamedTimers->lower_bound(Name); 189 if (I != NamedTimers->end() && I->first == Name) 190 return I->second; 191 192 return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second; 193} 194 195NamedRegionTimer::NamedRegionTimer(const std::string &Name) 196 : TimeRegion(getNamedRegionTimer(Name)) {} 197 198 199//===----------------------------------------------------------------------===// 200// TimerGroup Implementation 201//===----------------------------------------------------------------------===// 202 203// printAlignedFP - Simulate the printf "%A.Bf" format, where A is the 204// TotalWidth size, and B is the AfterDec size. 205// 206static void printAlignedFP(double Val, unsigned AfterDec, unsigned TotalWidth, 207 std::ostream &OS) { 208 assert(TotalWidth >= AfterDec+1 && "Bad FP Format!"); 209 OS.width(TotalWidth-AfterDec-1); 210 char OldFill = OS.fill(); 211 OS.fill(' '); 212 OS << (int)Val; // Integer part; 213 OS << "."; 214 OS.width(AfterDec); 215 OS.fill('0'); 216 unsigned ResultFieldSize = 1; 217 while (AfterDec--) ResultFieldSize *= 10; 218 OS << (int)(Val*ResultFieldSize) % ResultFieldSize; 219 OS.fill(OldFill); 220} 221 222static void printVal(double Val, double Total, std::ostream &OS) { 223 if (Total < 1e-7) // Avoid dividing by zero... 224 OS << " ----- "; 225 else { 226 OS << " "; 227 printAlignedFP(Val, 4, 7, OS); 228 OS << " ("; 229 printAlignedFP(Val*100/Total, 1, 5, OS); 230 OS << "%)"; 231 } 232} 233 234void Timer::print(const Timer &Total, std::ostream &OS) { 235 if (Total.UserTime) 236 printVal(UserTime, Total.UserTime, OS); 237 if (Total.SystemTime) 238 printVal(SystemTime, Total.SystemTime, OS); 239 if (Total.getProcessTime()) 240 printVal(getProcessTime(), Total.getProcessTime(), OS); 241 printVal(Elapsed, Total.Elapsed, OS); 242 243 OS << " "; 244 245 if (Total.MemUsed) { 246 OS.width(9); 247 OS << MemUsed << " "; 248 } 249 if (Total.PeakMem) { 250 if (PeakMem) { 251 OS.width(9); 252 OS << PeakMem << " "; 253 } else 254 OS << " "; 255 } 256 OS << Name << "\n"; 257 258 Started = false; // Once printed, don't print again 259} 260 261// GetLibSupportInfoOutputFile - Return a file stream to print our output on... 262std::ostream * 263llvm::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"; 307 308 // If this is not an collection of ungrouped times, print the total time. 309 // Ungrouped timers don't really make sense to add up. We still print the 310 // TOTAL line to make the percentages make sense. 311 if (this != DefaultTimerGroup) { 312 *OutStream << " Total Execution Time: "; 313 314 printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream); 315 *OutStream << " seconds ("; 316 printAlignedFP(Total.getWallTime(), 4, 5, *OutStream); 317 *OutStream << " wall clock)\n"; 318 } 319 *OutStream << "\n"; 320 321 if (Total.UserTime) 322 *OutStream << " ---User Time---"; 323 if (Total.SystemTime) 324 *OutStream << " --System Time--"; 325 if (Total.getProcessTime()) 326 *OutStream << " --User+System--"; 327 *OutStream << " ---Wall Time---"; 328 if (Total.getMemUsed()) 329 *OutStream << " ---Mem---"; 330 if (Total.getPeakMem()) 331 *OutStream << " -PeakMem-"; 332 *OutStream << " --- Name ---\n"; 333 334 // Loop through all of the timing data, printing it out... 335 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 336 TimersToPrint[i].print(Total, *OutStream); 337 338 Total.print(Total, *OutStream); 339 *OutStream << std::endl; // Flush output 340 } 341 --NumTimers; 342 343 TimersToPrint.clear(); 344 345 if (OutStream != &std::cerr && OutStream != &std::cout) 346 delete OutStream; // Close the file... 347 } 348 349 // Delete default timer group! 350 if (NumTimers == 0 && this == DefaultTimerGroup) { 351 delete DefaultTimerGroup; 352 DefaultTimerGroup = 0; 353 } 354} 355 356