579 lines · cpp
1//===-- Timer.cpp - Interval Timing Support -------------------------------===//2//3// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.4// See https://llvm.org/LICENSE.txt for license information.5// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception6//7//===----------------------------------------------------------------------===//8//9/// \file Interval Timing implementation.10//11//===----------------------------------------------------------------------===//12 13#include "llvm/Support/Timer.h"14 15#include "DebugOptions.h"16 17#include "llvm/ADT/Statistic.h"18#include "llvm/ADT/StringMap.h"19#include "llvm/Config/config.h"20#include "llvm/Support/CommandLine.h"21#include "llvm/Support/FileSystem.h"22#include "llvm/Support/Format.h"23#include "llvm/Support/ManagedStatic.h"24#include "llvm/Support/Mutex.h"25#include "llvm/Support/Process.h"26#include "llvm/Support/Signposts.h"27#include "llvm/Support/raw_ostream.h"28#include <limits>29#include <optional>30 31#if HAVE_UNISTD_H32#include <unistd.h>33#endif34 35#ifdef HAVE_PROC_PID_RUSAGE36#include <libproc.h>37#endif38 39using namespace llvm;40 41//===----------------------------------------------------------------------===//42// Forward declarations for Managed Timer Globals getters.43//44// Globals have been placed at the end of the file to restrict direct45// access. Use of getters also has the benefit of making it a bit more explicit46// that a global is being used.47//===----------------------------------------------------------------------===//48namespace {49class Name2PairMap;50}51 52static std::string &libSupportInfoOutputFilename();53static bool trackSpace();54static bool sortTimers();55[[maybe_unused]]56static SignpostEmitter &signposts();57static sys::SmartMutex<true> &timerLock();58static TimerGroup &defaultTimerGroup();59static Name2PairMap &namedGroupedTimers();60static bool isTimerGlobalsConstructed();61 62//===----------------------------------------------------------------------===//63//64//===----------------------------------------------------------------------===//65 66std::unique_ptr<raw_ostream> llvm::CreateInfoOutputFile() {67 const std::string &OutputFilename = libSupportInfoOutputFilename();68 if (OutputFilename.empty())69 return std::make_unique<raw_fd_ostream>(2, false); // stderr.70 if (OutputFilename == "-")71 return std::make_unique<raw_fd_ostream>(1, false); // stdout.72 73 // Append mode is used because the info output file is opened and closed74 // each time -stats or -time-passes wants to print output to it. To75 // compensate for this, the test-suite Makefiles have code to delete the76 // info output file before running commands which write to it.77 std::error_code EC;78 auto Result = std::make_unique<raw_fd_ostream>(79 OutputFilename, EC, sys::fs::OF_Append | sys::fs::OF_TextWithCRLF);80 if (!EC)81 return Result;82 83 errs() << "Error opening info-output-file '"84 << OutputFilename << " for appending!\n";85 return std::make_unique<raw_fd_ostream>(2, false); // stderr.86}87 88//===----------------------------------------------------------------------===//89// Timer Implementation90//===----------------------------------------------------------------------===//91 92void Timer::init(StringRef TimerName, StringRef TimerDescription) {93 init(TimerName, TimerDescription, defaultTimerGroup());94}95 96void Timer::init(StringRef TimerName, StringRef TimerDescription,97 TimerGroup &tg) {98 assert(!TG && "Timer already initialized");99 Name.assign(TimerName.begin(), TimerName.end());100 Description.assign(TimerDescription.begin(), TimerDescription.end());101 Running = Triggered = false;102 TG = &tg;103 TG->addTimer(*this);104}105 106Timer::~Timer() {107 if (!TG) return; // Never initialized, or already cleared.108 TG->removeTimer(*this);109}110 111static inline size_t getMemUsage() {112 if (!trackSpace())113 return 0;114 return sys::Process::GetMallocUsage();115}116 117static uint64_t getCurInstructionsExecuted() {118#if defined(HAVE_UNISTD_H) && defined(HAVE_PROC_PID_RUSAGE) && \119 defined(RUSAGE_INFO_V4)120 struct rusage_info_v4 ru;121 if (proc_pid_rusage(getpid(), RUSAGE_INFO_V4, (rusage_info_t *)&ru) == 0) {122 return ru.ri_instructions;123 }124#endif125 return 0;126}127 128TimeRecord TimeRecord::getCurrentTime(bool Start) {129 using Seconds = std::chrono::duration<double, std::ratio<1>>;130 TimeRecord Result;131 sys::TimePoint<> now;132 std::chrono::nanoseconds user, sys;133 134 if (Start) {135 Result.MemUsed = getMemUsage();136 Result.InstructionsExecuted = getCurInstructionsExecuted();137 sys::Process::GetTimeUsage(now, user, sys);138 } else {139 sys::Process::GetTimeUsage(now, user, sys);140 Result.InstructionsExecuted = getCurInstructionsExecuted();141 Result.MemUsed = getMemUsage();142 }143 144 Result.WallTime = Seconds(now.time_since_epoch()).count();145 Result.UserTime = Seconds(user).count();146 Result.SystemTime = Seconds(sys).count();147 return Result;148}149 150void Timer::startTimer() {151 assert(!Running && "Cannot start a running timer");152 Running = Triggered = true;153#if LLVM_SUPPORT_XCODE_SIGNPOSTS154 signposts().startInterval(this, getName());155#endif156 StartTime = TimeRecord::getCurrentTime(true);157}158 159void Timer::stopTimer() {160 assert(Running && "Cannot stop a paused timer");161 Running = false;162 Time += TimeRecord::getCurrentTime(false);163 Time -= StartTime;164#if LLVM_SUPPORT_XCODE_SIGNPOSTS165 signposts().endInterval(this, getName());166#endif167}168 169void Timer::clear() {170 Running = Triggered = false;171 Time = StartTime = TimeRecord();172}173 174void Timer::yieldTo(Timer &O) {175 stopTimer();176 O.startTimer();177}178 179static void printVal(double Val, double Total, raw_ostream &OS) {180 if (Total < 1e-7) // Avoid dividing by zero.181 OS << " ----- ";182 else183 OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);184}185 186void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {187 if (Total.getUserTime())188 printVal(getUserTime(), Total.getUserTime(), OS);189 if (Total.getSystemTime())190 printVal(getSystemTime(), Total.getSystemTime(), OS);191 if (Total.getProcessTime())192 printVal(getProcessTime(), Total.getProcessTime(), OS);193 printVal(getWallTime(), Total.getWallTime(), OS);194 195 OS << " ";196 197 if (Total.getMemUsed())198 OS << format("%9" PRId64 " ", (int64_t)getMemUsed());199 if (Total.getInstructionsExecuted())200 OS << format("%9" PRId64 " ", (int64_t)getInstructionsExecuted());201}202 203 204//===----------------------------------------------------------------------===//205// NamedRegionTimer Implementation206//===----------------------------------------------------------------------===//207 208namespace {209 210using Name2TimerMap = StringMap<Timer>;211 212class Name2PairMap {213 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;214public:215 ~Name2PairMap() {216 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator217 I = Map.begin(), E = Map.end(); I != E; ++I)218 delete I->second.first;219 }220 221 Timer &get(StringRef Name, StringRef Description, StringRef GroupName,222 StringRef GroupDescription) {223 sys::SmartScopedLock<true> L(timerLock());224 225 std::pair<TimerGroup *, Name2TimerMap> &GroupEntry =226 getGroupEntry(GroupName, GroupDescription);227 Timer &T = GroupEntry.second[Name];228 if (!T.isInitialized())229 T.init(Name, Description, *GroupEntry.first);230 return T;231 }232 233 TimerGroup &getTimerGroup(StringRef GroupName, StringRef GroupDescription) {234 sys::SmartScopedLock<true> L(timerLock());235 return *getGroupEntry(GroupName, GroupDescription).first;236 }237 238private:239 std::pair<TimerGroup *, Name2TimerMap> &240 getGroupEntry(StringRef GroupName, StringRef GroupDescription) {241 std::pair<TimerGroup *, Name2TimerMap> &GroupEntry = Map[GroupName];242 if (!GroupEntry.first)243 GroupEntry.first =244 new TimerGroup(GroupName, GroupDescription, /*PrintOnExit=*/true);245 246 return GroupEntry;247 }248};249 250}251 252NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,253 StringRef GroupName,254 StringRef GroupDescription, bool Enabled)255 : TimeRegion(!Enabled256 ? nullptr257 : &namedGroupedTimers().get(Name, Description, GroupName,258 GroupDescription)) {}259 260TimerGroup &NamedRegionTimer::getNamedTimerGroup(StringRef GroupName,261 StringRef GroupDescription) {262 return namedGroupedTimers().getTimerGroup(GroupName, GroupDescription);263}264 265//===----------------------------------------------------------------------===//266// TimerGroup Implementation267//===----------------------------------------------------------------------===//268 269/// This is the global list of TimerGroups, maintained by the TimerGroup270/// ctor/dtor and is protected by the timerLock lock.271static TimerGroup *TimerGroupList = nullptr;272 273TimerGroup::TimerGroup(StringRef Name, StringRef Description,274 sys::SmartMutex<true> &lock, bool PrintOnExit)275 : Name(Name.begin(), Name.end()),276 Description(Description.begin(), Description.end()),277 PrintOnExit(PrintOnExit) {278 // Add the group to TimerGroupList.279 sys::SmartScopedLock<true> L(lock);280 if (TimerGroupList)281 TimerGroupList->Prev = &Next;282 Next = TimerGroupList;283 Prev = &TimerGroupList;284 TimerGroupList = this;285}286 287TimerGroup::TimerGroup(StringRef Name, StringRef Description, bool PrintOnExit)288 : TimerGroup(Name, Description, timerLock(), PrintOnExit) {}289 290TimerGroup::TimerGroup(StringRef Name, StringRef Description,291 const StringMap<TimeRecord> &Records, bool PrintOnExit)292 : TimerGroup(Name, Description, PrintOnExit) {293 TimersToPrint.reserve(Records.size());294 for (const auto &P : Records)295 TimersToPrint.emplace_back(P.getValue(), std::string(P.getKey()),296 std::string(P.getKey()));297 assert(TimersToPrint.size() == Records.size() && "Size mismatch");298}299 300TimerGroup::~TimerGroup() {301 // If the timer group is destroyed before the timers it owns, accumulate and302 // print the timing data.303 while (FirstTimer)304 removeTimer(*FirstTimer);305 306 if (!TimersToPrint.empty() && PrintOnExit) {307 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();308 PrintQueuedTimers(*OutStream);309 }310 311 auto unlink = [&]() {312 *Prev = Next;313 if (Next)314 Next->Prev = Prev;315 };316 317 // TimerGlobals is always created implicity, through a call to timerLock(),318 // when a TimeGroup is created. On CRT shutdown, the TimerGlobals instance319 // might have been destroyed already. Avoid re-creating it if calling320 // timerLock().321 if (!isTimerGlobalsConstructed()) {322 unlink();323 return;324 }325 326 // Remove the group from the TimerGroupList.327 sys::SmartScopedLock<true> L(timerLock());328 unlink();329}330 331void TimerGroup::removeTimer(Timer &T) {332 sys::SmartScopedLock<true> L(timerLock());333 334 // If the timer was started, move its data to TimersToPrint.335 if (T.hasTriggered())336 TimersToPrint.emplace_back(T.Time, T.Name, T.Description);337 338 T.TG = nullptr;339 340 // Unlink the timer from our list.341 *T.Prev = T.Next;342 if (T.Next)343 T.Next->Prev = T.Prev;344}345 346void TimerGroup::addTimer(Timer &T) {347 sys::SmartScopedLock<true> L(timerLock());348 349 // Add the timer to our list.350 if (FirstTimer)351 FirstTimer->Prev = &T.Next;352 T.Next = FirstTimer;353 T.Prev = &FirstTimer;354 FirstTimer = &T;355}356 357void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {358 // Perhaps sort the timers in descending order by amount of time taken.359 if (sortTimers())360 llvm::sort(TimersToPrint);361 362 TimeRecord Total;363 for (const PrintRecord &Record : TimersToPrint)364 Total += Record.Time;365 366 // Print out timing header.367 OS << "===" << std::string(73, '-') << "===\n";368 // Figure out how many spaces to indent TimerGroup name.369 unsigned Padding = (80-Description.length())/2;370 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers371 OS.indent(Padding) << Description << '\n';372 OS << "===" << std::string(73, '-') << "===\n";373 374 // If this is not an collection of ungrouped times, print the total time.375 // Ungrouped timers don't really make sense to add up. We still print the376 // TOTAL line to make the percentages make sense.377 if (this != &defaultTimerGroup())378 OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",379 Total.getProcessTime(), Total.getWallTime());380 OS << '\n';381 382 if (Total.getUserTime())383 OS << " ---User Time---";384 if (Total.getSystemTime())385 OS << " --System Time--";386 if (Total.getProcessTime())387 OS << " --User+System--";388 OS << " ---Wall Time---";389 if (Total.getMemUsed())390 OS << " ---Mem---";391 if (Total.getInstructionsExecuted())392 OS << " ---Instr---";393 OS << " --- Name ---\n";394 395 // Loop through all of the timing data, printing it out.396 for (const PrintRecord &Record : llvm::reverse(TimersToPrint)) {397 Record.Time.print(Total, OS);398 OS << Record.Description << '\n';399 }400 401 Total.print(Total, OS);402 OS << "Total\n\n";403 OS.flush();404 405 TimersToPrint.clear();406}407 408void TimerGroup::prepareToPrintList(bool ResetTime) {409 // See if any of our timers were started, if so add them to TimersToPrint.410 for (Timer *T = FirstTimer; T; T = T->Next) {411 if (!T->hasTriggered()) continue;412 bool WasRunning = T->isRunning();413 if (WasRunning)414 T->stopTimer();415 416 TimersToPrint.emplace_back(T->Time, T->Name, T->Description);417 418 if (ResetTime)419 T->clear();420 421 if (WasRunning)422 T->startTimer();423 }424}425 426void TimerGroup::print(raw_ostream &OS, bool ResetAfterPrint) {427 {428 // After preparing the timers we can free the lock429 sys::SmartScopedLock<true> L(timerLock());430 prepareToPrintList(ResetAfterPrint);431 }432 433 // If any timers were started, print the group.434 if (!TimersToPrint.empty())435 PrintQueuedTimers(OS);436}437 438void TimerGroup::clear() {439 sys::SmartScopedLock<true> L(timerLock());440 for (Timer *T = FirstTimer; T; T = T->Next)441 T->clear();442}443 444void TimerGroup::printAll(raw_ostream &OS) {445 sys::SmartScopedLock<true> L(timerLock());446 447 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)448 TG->print(OS);449}450 451void TimerGroup::clearAll() {452 sys::SmartScopedLock<true> L(timerLock());453 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)454 TG->clear();455}456 457void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,458 const char *suffix, double Value) {459 constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;460 OS << "\t\"time." << Name << '.' << R.Name << suffix461 << "\": " << format("%.*e", max_digits10 - 1, Value);462}463 464const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {465 sys::SmartScopedLock<true> L(timerLock());466 467 prepareToPrintList(false);468 for (const PrintRecord &R : TimersToPrint) {469 OS << delim;470 delim = ",\n";471 472 const TimeRecord &T = R.Time;473 printJSONValue(OS, R, ".wall", T.getWallTime());474 OS << delim;475 printJSONValue(OS, R, ".user", T.getUserTime());476 OS << delim;477 printJSONValue(OS, R, ".sys", T.getSystemTime());478 if (T.getMemUsed()) {479 OS << delim;480 printJSONValue(OS, R, ".mem", T.getMemUsed());481 }482 if (T.getInstructionsExecuted()) {483 OS << delim;484 printJSONValue(OS, R, ".instr", T.getInstructionsExecuted());485 }486 }487 TimersToPrint.clear();488 return delim;489}490 491const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {492 sys::SmartScopedLock<true> L(timerLock());493 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)494 delim = TG->printJSONValues(OS, delim);495 return delim;496}497 498//===----------------------------------------------------------------------===//499// Timer Globals500//501// Previously, these were independent ManagedStatics. This led to bugs because502// there are dependencies between the globals, but no reliable mechanism to503// control relative lifetimes.504//505// Placing the globals within one class instance lets us control the lifetimes506// of the various data members and ensure that no global uses another that has507// been deleted.508//509// Globals fall into two categories. First are simple data types and510// command-line options. These are cheap to construct and/or required early511// during launch. They are created when the ManagedTimerGlobals singleton is512// constructed. Second are types that are more expensive to construct or not513// needed until later during compilation. These are lazily constructed in order514// to reduce launch time.515//===----------------------------------------------------------------------===//516class llvm::TimerGlobals {517public:518 std::string LibSupportInfoOutputFilename;519 cl::opt<std::string, true> InfoOutputFilename{520 "info-output-file", cl::value_desc("filename"),521 cl::desc("File to append -stats and -timer output to"), cl::Hidden,522 cl::location(LibSupportInfoOutputFilename)};523 cl::opt<bool> TrackSpace{524 "track-memory",525 cl::desc("Enable -time-passes memory tracking (this may be slow)"),526 cl::Hidden};527 cl::opt<bool> SortTimers{528 "sort-timers",529 cl::desc("In the report, sort the timers in each group in wall clock"530 " time order"),531 cl::init(true), cl::Hidden};532 533 sys::SmartMutex<true> TimerLock;534 TimerGroup DefaultTimerGroup{"misc", "Miscellaneous Ungrouped Timers",535 TimerLock, /*PrintOnExit=*/true};536 SignpostEmitter Signposts;537 538 // Order of these members and initialization below is important. For example539 // the defaultTimerGroup uses the timerLock. Most of these also depend on the540 // options above.541 std::once_flag InitDeferredFlag;542 std::optional<Name2PairMap> NamedGroupedTimersPtr;543 544 TimerGlobals &initDeferred() {545 std::call_once(InitDeferredFlag,546 [this]() { NamedGroupedTimersPtr.emplace(); });547 return *this;548 }549};550 551static ManagedStatic<TimerGlobals> ManagedTimerGlobals;552 553static std::string &libSupportInfoOutputFilename() {554 return ManagedTimerGlobals->LibSupportInfoOutputFilename;555}556static bool trackSpace() { return ManagedTimerGlobals->TrackSpace; }557static bool sortTimers() { return ManagedTimerGlobals->SortTimers; }558static SignpostEmitter &signposts() { return ManagedTimerGlobals->Signposts; }559static sys::SmartMutex<true> &timerLock() {560 return ManagedTimerGlobals->TimerLock;561}562static TimerGroup &defaultTimerGroup() {563 return ManagedTimerGlobals->DefaultTimerGroup;564}565static Name2PairMap &namedGroupedTimers() {566 return *ManagedTimerGlobals->initDeferred().NamedGroupedTimersPtr;567}568 569void llvm::initTimerOptions() { *ManagedTimerGlobals; }570void TimerGroup::constructForStatistics() {571 ManagedTimerGlobals->initDeferred();572}573 574void *TimerGroup::acquireTimerGlobals() { return ManagedTimerGlobals.claim(); }575 576static bool isTimerGlobalsConstructed() {577 return ManagedTimerGlobals.isConstructed();578}579