Timer.cpp revision 198090
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/ManagedStatic.h" 17#include "llvm/Support/raw_ostream.h" 18#include "llvm/Support/Format.h" 19#include "llvm/System/Process.h" 20#include <algorithm> 21#include <functional> 22#include <map> 23using namespace llvm; 24 25// GetLibSupportInfoOutputFile - Return a file stream to print our output on. 26namespace 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. 36static ManagedStatic<std::string> LibSupportInfoOutputFilename; 37static std::string &getLibSupportInfoOutputFilename() { 38 return *LibSupportInfoOutputFilename; 39} 40 41static ManagedStatic<sys::SmartMutex<true> > TimerLock; 42 43namespace { 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 55static TimerGroup *DefaultTimerGroup = 0; 56static TimerGroup *getDefaultTimerGroup() { 57 TimerGroup* tmp = DefaultTimerGroup; 58 sys::MemoryFence(); 59 if (!tmp) { 60 llvm_acquire_global_lock(); 61 tmp = DefaultTimerGroup; 62 if (!tmp) { 63 tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); 64 sys::MemoryFence(); 65 DefaultTimerGroup = tmp; 66 } 67 llvm_release_global_lock(); 68 } 69 70 return tmp; 71} 72 73Timer::Timer(const std::string &N) 74 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 75 Started(false), TG(getDefaultTimerGroup()) { 76 TG->addTimer(); 77} 78 79Timer::Timer(const std::string &N, TimerGroup &tg) 80 : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), 81 Started(false), TG(&tg) { 82 TG->addTimer(); 83} 84 85Timer::Timer(const Timer &T) { 86 TG = T.TG; 87 if (TG) TG->addTimer(); 88 operator=(T); 89} 90 91 92// Copy ctor, initialize with no TG member. 93Timer::Timer(bool, const Timer &T) { 94 TG = T.TG; // Avoid assertion in operator= 95 operator=(T); // Copy contents 96 TG = 0; 97} 98 99 100Timer::~Timer() { 101 if (TG) { 102 if (Started) { 103 Started = false; 104 TG->addTimerToPrint(*this); 105 } 106 TG->removeTimer(); 107 } 108} 109 110static inline size_t getMemUsage() { 111 if (TrackSpace) 112 return sys::Process::GetMallocUsage(); 113 return 0; 114} 115 116struct TimeRecord { 117 double Elapsed, UserTime, SystemTime; 118 ssize_t MemUsed; 119}; 120 121static TimeRecord getTimeRecord(bool Start) { 122 TimeRecord Result; 123 124 sys::TimeValue now(0,0); 125 sys::TimeValue user(0,0); 126 sys::TimeValue sys(0,0); 127 128 ssize_t MemUsed = 0; 129 if (Start) { 130 MemUsed = getMemUsage(); 131 sys::Process::GetTimeUsage(now,user,sys); 132 } else { 133 sys::Process::GetTimeUsage(now,user,sys); 134 MemUsed = getMemUsage(); 135 } 136 137 Result.Elapsed = now.seconds() + now.microseconds() / 1000000.0; 138 Result.UserTime = user.seconds() + user.microseconds() / 1000000.0; 139 Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0; 140 Result.MemUsed = MemUsed; 141 142 return Result; 143} 144 145static ManagedStatic<std::vector<Timer*> > ActiveTimers; 146 147void Timer::startTimer() { 148 sys::SmartScopedLock<true> L(Lock); 149 Started = true; 150 ActiveTimers->push_back(this); 151 TimeRecord TR = getTimeRecord(true); 152 Elapsed -= TR.Elapsed; 153 UserTime -= TR.UserTime; 154 SystemTime -= TR.SystemTime; 155 MemUsed -= TR.MemUsed; 156 PeakMemBase = TR.MemUsed; 157} 158 159void Timer::stopTimer() { 160 sys::SmartScopedLock<true> L(Lock); 161 TimeRecord TR = getTimeRecord(false); 162 Elapsed += TR.Elapsed; 163 UserTime += TR.UserTime; 164 SystemTime += TR.SystemTime; 165 MemUsed += TR.MemUsed; 166 167 if (ActiveTimers->back() == this) { 168 ActiveTimers->pop_back(); 169 } else { 170 std::vector<Timer*>::iterator I = 171 std::find(ActiveTimers->begin(), ActiveTimers->end(), this); 172 assert(I != ActiveTimers->end() && "stop but no startTimer?"); 173 ActiveTimers->erase(I); 174 } 175} 176 177void Timer::sum(const Timer &T) { 178 if (&T < this) { 179 T.Lock.acquire(); 180 Lock.acquire(); 181 } else { 182 Lock.acquire(); 183 T.Lock.acquire(); 184 } 185 186 Elapsed += T.Elapsed; 187 UserTime += T.UserTime; 188 SystemTime += T.SystemTime; 189 MemUsed += T.MemUsed; 190 PeakMem += T.PeakMem; 191 192 if (&T < this) { 193 T.Lock.release(); 194 Lock.release(); 195 } else { 196 Lock.release(); 197 T.Lock.release(); 198 } 199} 200 201/// addPeakMemoryMeasurement - This method should be called whenever memory 202/// usage needs to be checked. It adds a peak memory measurement to the 203/// currently active timers, which will be printed when the timer group prints 204/// 205void Timer::addPeakMemoryMeasurement() { 206 size_t MemUsed = getMemUsage(); 207 208 for (std::vector<Timer*>::iterator I = ActiveTimers->begin(), 209 E = ActiveTimers->end(); I != E; ++I) { 210 (*I)->Lock.acquire(); 211 (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase); 212 (*I)->Lock.release(); 213 } 214} 215 216//===----------------------------------------------------------------------===// 217// NamedRegionTimer Implementation 218//===----------------------------------------------------------------------===// 219 220namespace { 221 222typedef std::map<std::string, Timer> Name2Timer; 223typedef std::map<std::string, std::pair<TimerGroup, Name2Timer> > Name2Pair; 224 225} 226 227static ManagedStatic<Name2Timer> NamedTimers; 228 229static ManagedStatic<Name2Pair> NamedGroupedTimers; 230 231static Timer &getNamedRegionTimer(const std::string &Name) { 232 sys::SmartScopedLock<true> L(*TimerLock); 233 Name2Timer::iterator I = NamedTimers->find(Name); 234 if (I != NamedTimers->end()) 235 return I->second; 236 237 return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second; 238} 239 240static Timer &getNamedRegionTimer(const std::string &Name, 241 const std::string &GroupName) { 242 sys::SmartScopedLock<true> L(*TimerLock); 243 244 Name2Pair::iterator I = NamedGroupedTimers->find(GroupName); 245 if (I == NamedGroupedTimers->end()) { 246 TimerGroup TG(GroupName); 247 std::pair<TimerGroup, Name2Timer> Pair(TG, Name2Timer()); 248 I = NamedGroupedTimers->insert(I, std::make_pair(GroupName, Pair)); 249 } 250 251 Name2Timer::iterator J = I->second.second.find(Name); 252 if (J == I->second.second.end()) 253 J = I->second.second.insert(J, 254 std::make_pair(Name, 255 Timer(Name, 256 I->second.first))); 257 258 return J->second; 259} 260 261NamedRegionTimer::NamedRegionTimer(const std::string &Name) 262 : TimeRegion(getNamedRegionTimer(Name)) {} 263 264NamedRegionTimer::NamedRegionTimer(const std::string &Name, 265 const std::string &GroupName) 266 : TimeRegion(getNamedRegionTimer(Name, GroupName)) {} 267 268//===----------------------------------------------------------------------===// 269// TimerGroup Implementation 270//===----------------------------------------------------------------------===// 271 272 273static void printVal(double Val, double Total, raw_ostream &OS) { 274 if (Total < 1e-7) // Avoid dividing by zero... 275 OS << " ----- "; 276 else { 277 OS << " " << format("%7.4f", Val) << " ("; 278 OS << format("%5.1f", Val*100/Total) << "%)"; 279 } 280} 281 282void Timer::print(const Timer &Total, raw_ostream &OS) { 283 if (&Total < this) { 284 Total.Lock.acquire(); 285 Lock.acquire(); 286 } else { 287 Lock.acquire(); 288 Total.Lock.acquire(); 289 } 290 291 if (Total.UserTime) 292 printVal(UserTime, Total.UserTime, OS); 293 if (Total.SystemTime) 294 printVal(SystemTime, Total.SystemTime, OS); 295 if (Total.getProcessTime()) 296 printVal(getProcessTime(), Total.getProcessTime(), OS); 297 printVal(Elapsed, Total.Elapsed, OS); 298 299 OS << " "; 300 301 if (Total.MemUsed) { 302 OS << format("%9lld", (long long)MemUsed) << " "; 303 } 304 if (Total.PeakMem) { 305 if (PeakMem) { 306 OS << format("%9lld", (long long)PeakMem) << " "; 307 } else 308 OS << " "; 309 } 310 OS << Name << "\n"; 311 312 Started = false; // Once printed, don't print again 313 314 if (&Total < this) { 315 Total.Lock.release(); 316 Lock.release(); 317 } else { 318 Lock.release(); 319 Total.Lock.release(); 320 } 321} 322 323// GetLibSupportInfoOutputFile - Return a file stream to print our output on... 324raw_ostream * 325llvm::GetLibSupportInfoOutputFile() { 326 std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename(); 327 if (LibSupportInfoOutputFilename.empty()) 328 return &errs(); 329 if (LibSupportInfoOutputFilename == "-") 330 return &outs(); 331 332 333 std::string Error; 334 raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(), 335 Error, raw_fd_ostream::F_Append); 336 if (Error.empty()) 337 return Result; 338 339 errs() << "Error opening info-output-file '" 340 << LibSupportInfoOutputFilename << " for appending!\n"; 341 delete Result; 342 return &errs(); 343} 344 345 346void TimerGroup::removeTimer() { 347 sys::SmartScopedLock<true> L(*TimerLock); 348 if (--NumTimers == 0 && !TimersToPrint.empty()) { // Print timing report... 349 // Sort the timers in descending order by amount of time taken... 350 std::sort(TimersToPrint.begin(), TimersToPrint.end(), 351 std::greater<Timer>()); 352 353 // Figure out how many spaces to indent TimerGroup name... 354 unsigned Padding = (80-Name.length())/2; 355 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers 356 357 raw_ostream *OutStream = GetLibSupportInfoOutputFile(); 358 359 ++NumTimers; 360 { // Scope to contain Total timer... don't allow total timer to drop us to 361 // zero timers... 362 Timer Total("TOTAL"); 363 364 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 365 Total.sum(TimersToPrint[i]); 366 367 // Print out timing header... 368 *OutStream << "===" << std::string(73, '-') << "===\n" 369 << std::string(Padding, ' ') << Name << "\n" 370 << "===" << std::string(73, '-') 371 << "===\n"; 372 373 // If this is not an collection of ungrouped times, print the total time. 374 // Ungrouped timers don't really make sense to add up. We still print the 375 // TOTAL line to make the percentages make sense. 376 if (this != DefaultTimerGroup) { 377 *OutStream << " Total Execution Time: "; 378 379 *OutStream << format("%5.4f", Total.getProcessTime()) << " seconds ("; 380 *OutStream << format("%5.4f", Total.getWallTime()) << " wall clock)\n"; 381 } 382 *OutStream << "\n"; 383 384 if (Total.UserTime) 385 *OutStream << " ---User Time---"; 386 if (Total.SystemTime) 387 *OutStream << " --System Time--"; 388 if (Total.getProcessTime()) 389 *OutStream << " --User+System--"; 390 *OutStream << " ---Wall Time---"; 391 if (Total.getMemUsed()) 392 *OutStream << " ---Mem---"; 393 if (Total.getPeakMem()) 394 *OutStream << " -PeakMem-"; 395 *OutStream << " --- Name ---\n"; 396 397 // Loop through all of the timing data, printing it out... 398 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 399 TimersToPrint[i].print(Total, *OutStream); 400 401 Total.print(Total, *OutStream); 402 *OutStream << '\n'; 403 OutStream->flush(); 404 } 405 --NumTimers; 406 407 TimersToPrint.clear(); 408 409 if (OutStream != &errs() && OutStream != &outs()) 410 delete OutStream; // Close the file... 411 } 412} 413 414void TimerGroup::addTimer() { 415 sys::SmartScopedLock<true> L(*TimerLock); 416 ++NumTimers; 417} 418 419void TimerGroup::addTimerToPrint(const Timer &T) { 420 sys::SmartScopedLock<true> L(*TimerLock); 421 TimersToPrint.push_back(Timer(true, T)); 422} 423 424