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