Timer.cpp revision 288943
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/ADT/StringMap.h" 16#include "llvm/Support/CommandLine.h" 17#include "llvm/Support/FileSystem.h" 18#include "llvm/Support/Format.h" 19#include "llvm/Support/ManagedStatic.h" 20#include "llvm/Support/Mutex.h" 21#include "llvm/Support/Process.h" 22#include "llvm/Support/raw_ostream.h" 23using namespace llvm; 24 25// CreateInfoOutputFile - Return a file stream to print our output on. 26namespace llvm { extern raw_ostream *CreateInfoOutputFile(); } 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 55// CreateInfoOutputFile - Return a file stream to print our output on. 56raw_ostream *llvm::CreateInfoOutputFile() { 57 const std::string &OutputFilename = getLibSupportInfoOutputFilename(); 58 if (OutputFilename.empty()) 59 return new raw_fd_ostream(2, false); // stderr. 60 if (OutputFilename == "-") 61 return new raw_fd_ostream(1, false); // stdout. 62 63 // Append mode is used because the info output file is opened and closed 64 // each time -stats or -time-passes wants to print output to it. To 65 // compensate for this, the test-suite Makefiles have code to delete the 66 // info output file before running commands which write to it. 67 std::error_code EC; 68 raw_ostream *Result = new raw_fd_ostream(OutputFilename, EC, 69 sys::fs::F_Append | sys::fs::F_Text); 70 if (!EC) 71 return Result; 72 73 errs() << "Error opening info-output-file '" 74 << OutputFilename << " for appending!\n"; 75 delete Result; 76 return new raw_fd_ostream(2, false); // stderr. 77} 78 79 80static TimerGroup *DefaultTimerGroup = nullptr; 81static TimerGroup *getDefaultTimerGroup() { 82 TimerGroup *tmp = DefaultTimerGroup; 83 sys::MemoryFence(); 84 if (tmp) return tmp; 85 86 sys::SmartScopedLock<true> Lock(*TimerLock); 87 tmp = DefaultTimerGroup; 88 if (!tmp) { 89 tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); 90 sys::MemoryFence(); 91 DefaultTimerGroup = tmp; 92 } 93 94 return tmp; 95} 96 97//===----------------------------------------------------------------------===// 98// Timer Implementation 99//===----------------------------------------------------------------------===// 100 101void Timer::init(StringRef N) { 102 assert(!TG && "Timer already initialized"); 103 Name.assign(N.begin(), N.end()); 104 Started = false; 105 TG = getDefaultTimerGroup(); 106 TG->addTimer(*this); 107} 108 109void Timer::init(StringRef N, TimerGroup &tg) { 110 assert(!TG && "Timer already initialized"); 111 Name.assign(N.begin(), N.end()); 112 Started = false; 113 TG = &tg; 114 TG->addTimer(*this); 115} 116 117Timer::~Timer() { 118 if (!TG) return; // Never initialized, or already cleared. 119 TG->removeTimer(*this); 120} 121 122static inline size_t getMemUsage() { 123 if (!TrackSpace) return 0; 124 return sys::Process::GetMallocUsage(); 125} 126 127TimeRecord TimeRecord::getCurrentTime(bool Start) { 128 TimeRecord Result; 129 sys::TimeValue now(0,0), user(0,0), sys(0,0); 130 131 if (Start) { 132 Result.MemUsed = getMemUsage(); 133 sys::Process::GetTimeUsage(now, user, sys); 134 } else { 135 sys::Process::GetTimeUsage(now, user, sys); 136 Result.MemUsed = getMemUsage(); 137 } 138 139 Result.WallTime = now.seconds() + now.microseconds() / 1000000.0; 140 Result.UserTime = user.seconds() + user.microseconds() / 1000000.0; 141 Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0; 142 return Result; 143} 144 145static ManagedStatic<std::vector<Timer*> > ActiveTimers; 146 147void Timer::startTimer() { 148 Started = true; 149 ActiveTimers->push_back(this); 150 Time -= TimeRecord::getCurrentTime(true); 151} 152 153void Timer::stopTimer() { 154 Time += TimeRecord::getCurrentTime(false); 155 156 if (ActiveTimers->back() == this) { 157 ActiveTimers->pop_back(); 158 } else { 159 std::vector<Timer*>::iterator I = 160 std::find(ActiveTimers->begin(), ActiveTimers->end(), this); 161 assert(I != ActiveTimers->end() && "stop but no startTimer?"); 162 ActiveTimers->erase(I); 163 } 164} 165 166static void printVal(double Val, double Total, raw_ostream &OS) { 167 if (Total < 1e-7) // Avoid dividing by zero. 168 OS << " ----- "; 169 else 170 OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total); 171} 172 173void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const { 174 if (Total.getUserTime()) 175 printVal(getUserTime(), Total.getUserTime(), OS); 176 if (Total.getSystemTime()) 177 printVal(getSystemTime(), Total.getSystemTime(), OS); 178 if (Total.getProcessTime()) 179 printVal(getProcessTime(), Total.getProcessTime(), OS); 180 printVal(getWallTime(), Total.getWallTime(), OS); 181 182 OS << " "; 183 184 if (Total.getMemUsed()) 185 OS << format("%9" PRId64 " ", (int64_t)getMemUsed()); 186} 187 188 189//===----------------------------------------------------------------------===// 190// NamedRegionTimer Implementation 191//===----------------------------------------------------------------------===// 192 193namespace { 194 195typedef StringMap<Timer> Name2TimerMap; 196 197class Name2PairMap { 198 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map; 199public: 200 ~Name2PairMap() { 201 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator 202 I = Map.begin(), E = Map.end(); I != E; ++I) 203 delete I->second.first; 204 } 205 206 Timer &get(StringRef Name, StringRef GroupName) { 207 sys::SmartScopedLock<true> L(*TimerLock); 208 209 std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName]; 210 211 if (!GroupEntry.first) 212 GroupEntry.first = new TimerGroup(GroupName); 213 214 Timer &T = GroupEntry.second[Name]; 215 if (!T.isInitialized()) 216 T.init(Name, *GroupEntry.first); 217 return T; 218 } 219}; 220 221} 222 223static ManagedStatic<Name2TimerMap> NamedTimers; 224static ManagedStatic<Name2PairMap> NamedGroupedTimers; 225 226static Timer &getNamedRegionTimer(StringRef Name) { 227 sys::SmartScopedLock<true> L(*TimerLock); 228 229 Timer &T = (*NamedTimers)[Name]; 230 if (!T.isInitialized()) 231 T.init(Name); 232 return T; 233} 234 235NamedRegionTimer::NamedRegionTimer(StringRef Name, 236 bool Enabled) 237 : TimeRegion(!Enabled ? nullptr : &getNamedRegionTimer(Name)) {} 238 239NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName, 240 bool Enabled) 241 : TimeRegion(!Enabled ? nullptr : &NamedGroupedTimers->get(Name, GroupName)){} 242 243//===----------------------------------------------------------------------===// 244// TimerGroup Implementation 245//===----------------------------------------------------------------------===// 246 247/// TimerGroupList - This is the global list of TimerGroups, maintained by the 248/// TimerGroup ctor/dtor and is protected by the TimerLock lock. 249static TimerGroup *TimerGroupList = nullptr; 250 251TimerGroup::TimerGroup(StringRef name) 252 : Name(name.begin(), name.end()), FirstTimer(nullptr) { 253 254 // Add the group to TimerGroupList. 255 sys::SmartScopedLock<true> L(*TimerLock); 256 if (TimerGroupList) 257 TimerGroupList->Prev = &Next; 258 Next = TimerGroupList; 259 Prev = &TimerGroupList; 260 TimerGroupList = this; 261} 262 263TimerGroup::~TimerGroup() { 264 // If the timer group is destroyed before the timers it owns, accumulate and 265 // print the timing data. 266 while (FirstTimer) 267 removeTimer(*FirstTimer); 268 269 // Remove the group from the TimerGroupList. 270 sys::SmartScopedLock<true> L(*TimerLock); 271 *Prev = Next; 272 if (Next) 273 Next->Prev = Prev; 274} 275 276 277void TimerGroup::removeTimer(Timer &T) { 278 sys::SmartScopedLock<true> L(*TimerLock); 279 280 // If the timer was started, move its data to TimersToPrint. 281 if (T.Started) 282 TimersToPrint.push_back(std::make_pair(T.Time, T.Name)); 283 284 T.TG = nullptr; 285 286 // Unlink the timer from our list. 287 *T.Prev = T.Next; 288 if (T.Next) 289 T.Next->Prev = T.Prev; 290 291 // Print the report when all timers in this group are destroyed if some of 292 // them were started. 293 if (FirstTimer || TimersToPrint.empty()) 294 return; 295 296 raw_ostream *OutStream = CreateInfoOutputFile(); 297 PrintQueuedTimers(*OutStream); 298 delete OutStream; // Close the file. 299} 300 301void TimerGroup::addTimer(Timer &T) { 302 sys::SmartScopedLock<true> L(*TimerLock); 303 304 // Add the timer to our list. 305 if (FirstTimer) 306 FirstTimer->Prev = &T.Next; 307 T.Next = FirstTimer; 308 T.Prev = &FirstTimer; 309 FirstTimer = &T; 310} 311 312void TimerGroup::PrintQueuedTimers(raw_ostream &OS) { 313 // Sort the timers in descending order by amount of time taken. 314 std::sort(TimersToPrint.begin(), TimersToPrint.end()); 315 316 TimeRecord Total; 317 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 318 Total += TimersToPrint[i].first; 319 320 // Print out timing header. 321 OS << "===" << std::string(73, '-') << "===\n"; 322 // Figure out how many spaces to indent TimerGroup name. 323 unsigned Padding = (80-Name.length())/2; 324 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers 325 OS.indent(Padding) << Name << '\n'; 326 OS << "===" << std::string(73, '-') << "===\n"; 327 328 // If this is not an collection of ungrouped times, print the total time. 329 // Ungrouped timers don't really make sense to add up. We still print the 330 // TOTAL line to make the percentages make sense. 331 if (this != DefaultTimerGroup) 332 OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n", 333 Total.getProcessTime(), Total.getWallTime()); 334 OS << '\n'; 335 336 if (Total.getUserTime()) 337 OS << " ---User Time---"; 338 if (Total.getSystemTime()) 339 OS << " --System Time--"; 340 if (Total.getProcessTime()) 341 OS << " --User+System--"; 342 OS << " ---Wall Time---"; 343 if (Total.getMemUsed()) 344 OS << " ---Mem---"; 345 OS << " --- Name ---\n"; 346 347 // Loop through all of the timing data, printing it out. 348 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) { 349 const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1]; 350 Entry.first.print(Total, OS); 351 OS << Entry.second << '\n'; 352 } 353 354 Total.print(Total, OS); 355 OS << "Total\n\n"; 356 OS.flush(); 357 358 TimersToPrint.clear(); 359} 360 361/// print - Print any started timers in this group and zero them. 362void TimerGroup::print(raw_ostream &OS) { 363 sys::SmartScopedLock<true> L(*TimerLock); 364 365 // See if any of our timers were started, if so add them to TimersToPrint and 366 // reset them. 367 for (Timer *T = FirstTimer; T; T = T->Next) { 368 if (!T->Started) continue; 369 TimersToPrint.push_back(std::make_pair(T->Time, T->Name)); 370 371 // Clear out the time. 372 T->Started = 0; 373 T->Time = TimeRecord(); 374 } 375 376 // If any timers were started, print the group. 377 if (!TimersToPrint.empty()) 378 PrintQueuedTimers(OS); 379} 380 381/// printAll - This static method prints all timers and clears them all out. 382void TimerGroup::printAll(raw_ostream &OS) { 383 sys::SmartScopedLock<true> L(*TimerLock); 384 385 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next) 386 TG->print(OS); 387} 388