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 /// \file Interval Timing implementation. 11 // 12 //===----------------------------------------------------------------------===// 13 14 #include "llvm/Support/Timer.h" 15 #include "llvm/ADT/Statistic.h" 16 #include "llvm/ADT/StringMap.h" 17 #include "llvm/Support/CommandLine.h" 18 #include "llvm/Support/FileSystem.h" 19 #include "llvm/Support/Format.h" 20 #include "llvm/Support/ManagedStatic.h" 21 #include "llvm/Support/Mutex.h" 22 #include "llvm/Support/Process.h" 23 #include "llvm/Support/raw_ostream.h" 24 #include "llvm/Support/YAMLTraits.h" 25 using namespace llvm; 26 27 // This ugly hack is brought to you courtesy of constructor/destructor ordering 28 // being unspecified by C++. Basically the problem is that a Statistic object 29 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()' 30 // (below), which calls this function. LibSupportInfoOutputFilename used to be 31 // a global variable, but sometimes it would get destroyed before the Statistic, 32 // causing havoc to ensue. We "fix" this by creating the string the first time 33 // it is needed and never destroying it. 34 static ManagedStatic<std::string> LibSupportInfoOutputFilename; 35 static std::string &getLibSupportInfoOutputFilename() { 36 return *LibSupportInfoOutputFilename; 37 } 38 39 static ManagedStatic<sys::SmartMutex<true> > TimerLock; 40 41 namespace { 42 static cl::opt<bool> 43 TrackSpace("track-memory", cl::desc("Enable -time-passes memory " 44 "tracking (this may be slow)"), 45 cl::Hidden); 46 47 static 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 53 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() { 54 const std::string &OutputFilename = getLibSupportInfoOutputFilename(); 55 if (OutputFilename.empty()) 56 return llvm::make_unique<raw_fd_ostream>(2, false); // stderr. 57 if (OutputFilename == "-") 58 return llvm::make_unique<raw_fd_ostream>(1, false); // stdout. 59 60 // Append mode is used because the info output file is opened and closed 61 // each time -stats or -time-passes wants to print output to it. To 62 // compensate for this, the test-suite Makefiles have code to delete the 63 // info output file before running commands which write to it. 64 std::error_code EC; 65 auto Result = llvm::make_unique<raw_fd_ostream>( 66 OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text); 67 if (!EC) 68 return Result; 69 70 errs() << "Error opening info-output-file '" 71 << OutputFilename << " for appending!\n"; 72 return llvm::make_unique<raw_fd_ostream>(2, false); // stderr. 73 } 74 75 76 static TimerGroup *DefaultTimerGroup = nullptr; 77 static TimerGroup *getDefaultTimerGroup() { 78 TimerGroup *tmp = DefaultTimerGroup; 79 sys::MemoryFence(); 80 if (tmp) return tmp; 81 82 sys::SmartScopedLock<true> Lock(*TimerLock); 83 tmp = DefaultTimerGroup; 84 if (!tmp) { 85 tmp = new TimerGroup("misc", "Miscellaneous Ungrouped Timers"); 86 sys::MemoryFence(); 87 DefaultTimerGroup = tmp; 88 } 89 90 return tmp; 91 } 92 93 //===----------------------------------------------------------------------===// 94 // Timer Implementation 95 //===----------------------------------------------------------------------===// 96 97 void Timer::init(StringRef Name, StringRef Description) { 98 init(Name, Description, *getDefaultTimerGroup()); 99 } 100 101 void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) { 102 assert(!TG && "Timer already initialized"); 103 this->Name.assign(Name.begin(), Name.end()); 104 this->Description.assign(Description.begin(), Description.end()); 105 Running = Triggered = false; 106 TG = &tg; 107 TG->addTimer(*this); 108 } 109 110 Timer::~Timer() { 111 if (!TG) return; // Never initialized, or already cleared. 112 TG->removeTimer(*this); 113 } 114 115 static inline size_t getMemUsage() { 116 if (!TrackSpace) return 0; 117 return sys::Process::GetMallocUsage(); 118 } 119 120 TimeRecord TimeRecord::getCurrentTime(bool Start) { 121 using Seconds = std::chrono::duration<double, std::ratio<1>>; 122 TimeRecord Result; 123 sys::TimePoint<> now; 124 std::chrono::nanoseconds user, sys; 125 126 if (Start) { 127 Result.MemUsed = getMemUsage(); 128 sys::Process::GetTimeUsage(now, user, sys); 129 } else { 130 sys::Process::GetTimeUsage(now, user, sys); 131 Result.MemUsed = getMemUsage(); 132 } 133 134 Result.WallTime = Seconds(now.time_since_epoch()).count(); 135 Result.UserTime = Seconds(user).count(); 136 Result.SystemTime = Seconds(sys).count(); 137 return Result; 138 } 139 140 void Timer::startTimer() { 141 assert(!Running && "Cannot start a running timer"); 142 Running = Triggered = true; 143 StartTime = TimeRecord::getCurrentTime(true); 144 } 145 146 void Timer::stopTimer() { 147 assert(Running && "Cannot stop a paused timer"); 148 Running = false; 149 Time += TimeRecord::getCurrentTime(false); 150 Time -= StartTime; 151 } 152 153 void Timer::clear() { 154 Running = Triggered = false; 155 Time = StartTime = TimeRecord(); 156 } 157 158 static void printVal(double Val, double Total, raw_ostream &OS) { 159 if (Total < 1e-7) // Avoid dividing by zero. 160 OS << " ----- "; 161 else 162 OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total); 163 } 164 165 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const { 166 if (Total.getUserTime()) 167 printVal(getUserTime(), Total.getUserTime(), OS); 168 if (Total.getSystemTime()) 169 printVal(getSystemTime(), Total.getSystemTime(), OS); 170 if (Total.getProcessTime()) 171 printVal(getProcessTime(), Total.getProcessTime(), OS); 172 printVal(getWallTime(), Total.getWallTime(), OS); 173 174 OS << " "; 175 176 if (Total.getMemUsed()) 177 OS << format("%9" PRId64 " ", (int64_t)getMemUsed()); 178 } 179 180 181 //===----------------------------------------------------------------------===// 182 // NamedRegionTimer Implementation 183 //===----------------------------------------------------------------------===// 184 185 namespace { 186 187 typedef StringMap<Timer> Name2TimerMap; 188 189 class Name2PairMap { 190 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map; 191 public: 192 ~Name2PairMap() { 193 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator 194 I = Map.begin(), E = Map.end(); I != E; ++I) 195 delete I->second.first; 196 } 197 198 Timer &get(StringRef Name, StringRef Description, StringRef GroupName, 199 StringRef GroupDescription) { 200 sys::SmartScopedLock<true> L(*TimerLock); 201 202 std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName]; 203 204 if (!GroupEntry.first) 205 GroupEntry.first = new TimerGroup(GroupName, GroupDescription); 206 207 Timer &T = GroupEntry.second[Name]; 208 if (!T.isInitialized()) 209 T.init(Name, Description, *GroupEntry.first); 210 return T; 211 } 212 }; 213 214 } 215 216 static ManagedStatic<Name2PairMap> NamedGroupedTimers; 217 218 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description, 219 StringRef GroupName, 220 StringRef GroupDescription, bool Enabled) 221 : TimeRegion(!Enabled ? nullptr 222 : &NamedGroupedTimers->get(Name, Description, GroupName, 223 GroupDescription)) {} 224 225 //===----------------------------------------------------------------------===// 226 // TimerGroup Implementation 227 //===----------------------------------------------------------------------===// 228 229 /// This is the global list of TimerGroups, maintained by the TimerGroup 230 /// ctor/dtor and is protected by the TimerLock lock. 231 static TimerGroup *TimerGroupList = nullptr; 232 233 TimerGroup::TimerGroup(StringRef Name, StringRef Description) 234 : Name(Name.begin(), Name.end()), 235 Description(Description.begin(), Description.end()) { 236 // Add the group to TimerGroupList. 237 sys::SmartScopedLock<true> L(*TimerLock); 238 if (TimerGroupList) 239 TimerGroupList->Prev = &Next; 240 Next = TimerGroupList; 241 Prev = &TimerGroupList; 242 TimerGroupList = this; 243 } 244 245 TimerGroup::~TimerGroup() { 246 // If the timer group is destroyed before the timers it owns, accumulate and 247 // print the timing data. 248 while (FirstTimer) 249 removeTimer(*FirstTimer); 250 251 // Remove the group from the TimerGroupList. 252 sys::SmartScopedLock<true> L(*TimerLock); 253 *Prev = Next; 254 if (Next) 255 Next->Prev = Prev; 256 } 257 258 259 void TimerGroup::removeTimer(Timer &T) { 260 sys::SmartScopedLock<true> L(*TimerLock); 261 262 // If the timer was started, move its data to TimersToPrint. 263 if (T.hasTriggered()) 264 TimersToPrint.emplace_back(T.Time, T.Name, T.Description); 265 266 T.TG = nullptr; 267 268 // Unlink the timer from our list. 269 *T.Prev = T.Next; 270 if (T.Next) 271 T.Next->Prev = T.Prev; 272 273 // Print the report when all timers in this group are destroyed if some of 274 // them were started. 275 if (FirstTimer || TimersToPrint.empty()) 276 return; 277 278 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile(); 279 PrintQueuedTimers(*OutStream); 280 } 281 282 void TimerGroup::addTimer(Timer &T) { 283 sys::SmartScopedLock<true> L(*TimerLock); 284 285 // Add the timer to our list. 286 if (FirstTimer) 287 FirstTimer->Prev = &T.Next; 288 T.Next = FirstTimer; 289 T.Prev = &FirstTimer; 290 FirstTimer = &T; 291 } 292 293 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) { 294 // Sort the timers in descending order by amount of time taken. 295 std::sort(TimersToPrint.begin(), TimersToPrint.end()); 296 297 TimeRecord Total; 298 for (const PrintRecord &Record : TimersToPrint) 299 Total += Record.Time; 300 301 // Print out timing header. 302 OS << "===" << std::string(73, '-') << "===\n"; 303 // Figure out how many spaces to indent TimerGroup name. 304 unsigned Padding = (80-Description.length())/2; 305 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers 306 OS.indent(Padding) << Description << '\n'; 307 OS << "===" << std::string(73, '-') << "===\n"; 308 309 // If this is not an collection of ungrouped times, print the total time. 310 // Ungrouped timers don't really make sense to add up. We still print the 311 // TOTAL line to make the percentages make sense. 312 if (this != DefaultTimerGroup) 313 OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n", 314 Total.getProcessTime(), Total.getWallTime()); 315 OS << '\n'; 316 317 if (Total.getUserTime()) 318 OS << " ---User Time---"; 319 if (Total.getSystemTime()) 320 OS << " --System Time--"; 321 if (Total.getProcessTime()) 322 OS << " --User+System--"; 323 OS << " ---Wall Time---"; 324 if (Total.getMemUsed()) 325 OS << " ---Mem---"; 326 OS << " --- Name ---\n"; 327 328 // Loop through all of the timing data, printing it out. 329 for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(), 330 TimersToPrint.rend())) { 331 Record.Time.print(Total, OS); 332 OS << Record.Description << '\n'; 333 } 334 335 Total.print(Total, OS); 336 OS << "Total\n\n"; 337 OS.flush(); 338 339 TimersToPrint.clear(); 340 } 341 342 void TimerGroup::prepareToPrintList() { 343 // See if any of our timers were started, if so add them to TimersToPrint and 344 // reset them. 345 for (Timer *T = FirstTimer; T; T = T->Next) { 346 if (!T->hasTriggered()) continue; 347 TimersToPrint.emplace_back(T->Time, T->Name, T->Description); 348 349 // Clear out the time. 350 T->clear(); 351 } 352 } 353 354 void TimerGroup::print(raw_ostream &OS) { 355 sys::SmartScopedLock<true> L(*TimerLock); 356 357 prepareToPrintList(); 358 359 // If any timers were started, print the group. 360 if (!TimersToPrint.empty()) 361 PrintQueuedTimers(OS); 362 } 363 364 void TimerGroup::printAll(raw_ostream &OS) { 365 sys::SmartScopedLock<true> L(*TimerLock); 366 367 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next) 368 TG->print(OS); 369 } 370 371 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R, 372 const char *suffix, double Value) { 373 assert(!yaml::needsQuotes(Name) && "TimerGroup name needs no quotes"); 374 assert(!yaml::needsQuotes(R.Name) && "Timer name needs no quotes"); 375 OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value; 376 } 377 378 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) { 379 prepareToPrintList(); 380 for (const PrintRecord &R : TimersToPrint) { 381 OS << delim; 382 delim = ",\n"; 383 384 const TimeRecord &T = R.Time; 385 printJSONValue(OS, R, ".wall", T.getWallTime()); 386 OS << delim; 387 printJSONValue(OS, R, ".user", T.getUserTime()); 388 OS << delim; 389 printJSONValue(OS, R, ".sys", T.getSystemTime()); 390 } 391 TimersToPrint.clear(); 392 return delim; 393 } 394 395 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) { 396 sys::SmartScopedLock<true> L(*TimerLock); 397 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next) 398 delim = TG->printJSONValues(OS, delim); 399 return delim; 400 } 401 402 void TimerGroup::ConstructTimerLists() { 403 (void)*NamedGroupedTimers; 404 } 405