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