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();
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>(args: 2, args: false); // stderr.
70 if (OutputFilename == "-")
71 return std::make_unique<raw_fd_ostream>(args: 1, args: false); // stdout.
72
73 // Append mode is used because the info output file is opened and closed
74 // each time -stats or -time-passes wants to print output to it. To
75 // compensate for this, the test-suite Makefiles have code to delete the
76 // 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 args: OutputFilename, args&: EC, args: 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>(args: 2, args: false); // stderr.
86}
87
88//===----------------------------------------------------------------------===//
89// Timer Implementation
90//===----------------------------------------------------------------------===//
91
92void Timer::init(StringRef TimerName, StringRef TimerDescription) {
93 init(TimerName, TimerDescription, tg&: defaultTimerGroup());
94}
95
96void Timer::init(StringRef TimerName, StringRef TimerDescription,
97 TimerGroup &tg) {
98 assert(!TG && "Timer already initialized");
99 Name.assign(first: TimerName.begin(), last: TimerName.end());
100 Description.assign(first: TimerDescription.begin(), last: TimerDescription.end());
101 Running = Triggered = false;
102 TG = &tg;
103 TG->addTimer(T&: *this);
104}
105
106Timer::~Timer() {
107 if (!TG) return; // Never initialized, or already cleared.
108 TG->removeTimer(T&: *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#endif
125 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(elapsed&: now, user_time&: user, sys_time&: sys);
138 } else {
139 sys::Process::GetTimeUsage(elapsed&: now, user_time&: user, sys_time&: 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_SIGNPOSTS
154 signposts().startInterval(this, getName());
155#endif
156 StartTime = TimeRecord::getCurrentTime(Start: true);
157}
158
159void Timer::stopTimer() {
160 assert(Running && "Cannot stop a paused timer");
161 Running = false;
162 Time += TimeRecord::getCurrentTime(Start: false);
163 Time -= StartTime;
164#if LLVM_SUPPORT_XCODE_SIGNPOSTS
165 signposts().endInterval(this, getName());
166#endif
167}
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 else
183 OS << format(Fmt: " %7.4f (%5.1f%%)", Vals: Val, Vals: Val*100/Total);
184}
185
186void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
187 if (Total.getUserTime())
188 printVal(Val: getUserTime(), Total: Total.getUserTime(), OS);
189 if (Total.getSystemTime())
190 printVal(Val: getSystemTime(), Total: Total.getSystemTime(), OS);
191 if (Total.getProcessTime())
192 printVal(Val: getProcessTime(), Total: Total.getProcessTime(), OS);
193 printVal(Val: getWallTime(), Total: Total.getWallTime(), OS);
194
195 OS << " ";
196
197 if (Total.getMemUsed())
198 OS << format(Fmt: "%9" PRId64 " ", Vals: (int64_t)getMemUsed());
199 if (Total.getInstructionsExecuted())
200 OS << format(Fmt: "%9" PRId64 " ", Vals: (int64_t)getInstructionsExecuted());
201}
202
203
204//===----------------------------------------------------------------------===//
205// NamedRegionTimer Implementation
206//===----------------------------------------------------------------------===//
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> >::iterator
217 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(TimerName: Name, TimerDescription: Description, tg&: *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(!Enabled
256 ? nullptr
257 : &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 Implementation
267//===----------------------------------------------------------------------===//
268
269/// This is the global list of TimerGroups, maintained by the TimerGroup
270/// 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(n: Records.size());
294 for (const auto &P : Records)
295 TimersToPrint.emplace_back(args: P.getValue(), args: std::string(P.getKey()),
296 args: 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 and
302 // print the timing data.
303 while (FirstTimer)
304 removeTimer(T&: *FirstTimer);
305
306 if (!TimersToPrint.empty() && PrintOnExit) {
307 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
308 PrintQueuedTimers(OS&: *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 instance
319 // might have been destroyed already. Avoid re-creating it if calling
320 // 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(args&: T.Time, args&: T.Name, args&: 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(C&: 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" numbers
371 OS.indent(NumSpaces: 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 the
376 // TOTAL line to make the percentages make sense.
377 if (this != &defaultTimerGroup())
378 OS << format(Fmt: " Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
379 Vals: Total.getProcessTime(), Vals: 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(C&: 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(args&: T->Time, args&: T->Name, args&: 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 lock
429 sys::SmartScopedLock<true> L(timerLock());
430 prepareToPrintList(ResetTime: 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 << suffix
461 << "\": " << format(Fmt: "%.*e", Vals: max_digits10 - 1, Vals: Value);
462}
463
464const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
465 sys::SmartScopedLock<true> L(timerLock());
466
467 prepareToPrintList(ResetTime: false);
468 for (const PrintRecord &R : TimersToPrint) {
469 OS << delim;
470 delim = ",\n";
471
472 const TimeRecord &T = R.Time;
473 printJSONValue(OS, R, suffix: ".wall", Value: T.getWallTime());
474 OS << delim;
475 printJSONValue(OS, R, suffix: ".user", Value: T.getUserTime());
476 OS << delim;
477 printJSONValue(OS, R, suffix: ".sys", Value: T.getSystemTime());
478 if (T.getMemUsed()) {
479 OS << delim;
480 printJSONValue(OS, R, suffix: ".mem", Value: T.getMemUsed());
481 }
482 if (T.getInstructionsExecuted()) {
483 OS << delim;
484 printJSONValue(OS, R, suffix: ".instr", Value: 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 Globals
500//
501// Previously, these were independent ManagedStatics. This led to bugs because
502// there are dependencies between the globals, but no reliable mechanism to
503// control relative lifetimes.
504//
505// Placing the globals within one class instance lets us control the lifetimes
506// of the various data members and ensure that no global uses another that has
507// been deleted.
508//
509// Globals fall into two categories. First are simple data types and
510// command-line options. These are cheap to construct and/or required early
511// during launch. They are created when the ManagedTimerGlobals singleton is
512// constructed. Second are types that are more expensive to construct or not
513// needed until later during compilation. These are lazily constructed in order
514// 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(L&: 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(Val: 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 example
539 // the defaultTimerGroup uses the timerLock. Most of these also depend on the
540 // options above.
541 std::once_flag InitDeferredFlag;
542 std::optional<Name2PairMap> NamedGroupedTimersPtr;
543
544 TimerGlobals &initDeferred() {
545 std::call_once(once&: InitDeferredFlag,
546 f: [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