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/YAMLTraits.h"
28#include "llvm/Support/raw_ostream.h"
29#include <limits>
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// This ugly hack is brought to you courtesy of constructor/destructor ordering
42// being unspecified by C++. Basically the problem is that a Statistic object
43// gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
44// (below), which calls this function. LibSupportInfoOutputFilename used to be
45// a global variable, but sometimes it would get destroyed before the Statistic,
46// causing havoc to ensue. We "fix" this by creating the string the first time
47// it is needed and never destroying it.
48static ManagedStatic<std::string> LibSupportInfoOutputFilename;
49static std::string &getLibSupportInfoOutputFilename() {
50 return *LibSupportInfoOutputFilename;
51}
52
53static ManagedStatic<sys::SmartMutex<true> > TimerLock;
54
55/// Allows llvm::Timer to emit signposts when supported.
56static ManagedStatic<SignpostEmitter> Signposts;
57
58namespace {
59struct CreateTrackSpace {
60 static void *call() {
61 return new cl::opt<bool>("track-memory",
62 cl::desc("Enable -time-passes memory "
63 "tracking (this may be slow)"),
64 cl::Hidden);
65 }
66};
67static ManagedStatic<cl::opt<bool>, CreateTrackSpace> TrackSpace;
68struct CreateInfoOutputFilename {
69 static void *call() {
70 return new cl::opt<std::string, true>(
71 "info-output-file", cl::value_desc("filename"),
72 cl::desc("File to append -stats and -timer output to"), cl::Hidden,
73 cl::location(L&: getLibSupportInfoOutputFilename()));
74 }
75};
76static ManagedStatic<cl::opt<std::string, true>, CreateInfoOutputFilename>
77 InfoOutputFilename;
78struct CreateSortTimers {
79 static void *call() {
80 return new cl::opt<bool>(
81 "sort-timers",
82 cl::desc("In the report, sort the timers in each group "
83 "in wall clock time order"),
84 cl::init(Val: true), cl::Hidden);
85 }
86};
87ManagedStatic<cl::opt<bool>, CreateSortTimers> SortTimers;
88} // namespace
89
90void llvm::initTimerOptions() {
91 *TrackSpace;
92 *InfoOutputFilename;
93 *SortTimers;
94}
95
96std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
97 const std::string &OutputFilename = getLibSupportInfoOutputFilename();
98 if (OutputFilename.empty())
99 return std::make_unique<raw_fd_ostream>(args: 2, args: false); // stderr.
100 if (OutputFilename == "-")
101 return std::make_unique<raw_fd_ostream>(args: 1, args: false); // stdout.
102
103 // Append mode is used because the info output file is opened and closed
104 // each time -stats or -time-passes wants to print output to it. To
105 // compensate for this, the test-suite Makefiles have code to delete the
106 // info output file before running commands which write to it.
107 std::error_code EC;
108 auto Result = std::make_unique<raw_fd_ostream>(
109 args: OutputFilename, args&: EC, args: sys::fs::OF_Append | sys::fs::OF_TextWithCRLF);
110 if (!EC)
111 return Result;
112
113 errs() << "Error opening info-output-file '"
114 << OutputFilename << " for appending!\n";
115 return std::make_unique<raw_fd_ostream>(args: 2, args: false); // stderr.
116}
117
118namespace {
119struct CreateDefaultTimerGroup {
120 static void *call() {
121 return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
122 }
123};
124} // namespace
125static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
126static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
127
128//===----------------------------------------------------------------------===//
129// Timer Implementation
130//===----------------------------------------------------------------------===//
131
132void Timer::init(StringRef TimerName, StringRef TimerDescription) {
133 init(TimerName, TimerDescription, tg&: *getDefaultTimerGroup());
134}
135
136void Timer::init(StringRef TimerName, StringRef TimerDescription,
137 TimerGroup &tg) {
138 assert(!TG && "Timer already initialized");
139 Name.assign(first: TimerName.begin(), last: TimerName.end());
140 Description.assign(first: TimerDescription.begin(), last: TimerDescription.end());
141 Running = Triggered = false;
142 TG = &tg;
143 TG->addTimer(T&: *this);
144}
145
146Timer::~Timer() {
147 if (!TG) return; // Never initialized, or already cleared.
148 TG->removeTimer(T&: *this);
149}
150
151static inline size_t getMemUsage() {
152 if (!*TrackSpace)
153 return 0;
154 return sys::Process::GetMallocUsage();
155}
156
157static uint64_t getCurInstructionsExecuted() {
158#if defined(HAVE_UNISTD_H) && defined(HAVE_PROC_PID_RUSAGE) && \
159 defined(RUSAGE_INFO_V4)
160 struct rusage_info_v4 ru;
161 if (proc_pid_rusage(getpid(), RUSAGE_INFO_V4, (rusage_info_t *)&ru) == 0) {
162 return ru.ri_instructions;
163 }
164#endif
165 return 0;
166}
167
168TimeRecord TimeRecord::getCurrentTime(bool Start) {
169 using Seconds = std::chrono::duration<double, std::ratio<1>>;
170 TimeRecord Result;
171 sys::TimePoint<> now;
172 std::chrono::nanoseconds user, sys;
173
174 if (Start) {
175 Result.MemUsed = getMemUsage();
176 Result.InstructionsExecuted = getCurInstructionsExecuted();
177 sys::Process::GetTimeUsage(elapsed&: now, user_time&: user, sys_time&: sys);
178 } else {
179 sys::Process::GetTimeUsage(elapsed&: now, user_time&: user, sys_time&: sys);
180 Result.InstructionsExecuted = getCurInstructionsExecuted();
181 Result.MemUsed = getMemUsage();
182 }
183
184 Result.WallTime = Seconds(now.time_since_epoch()).count();
185 Result.UserTime = Seconds(user).count();
186 Result.SystemTime = Seconds(sys).count();
187 return Result;
188}
189
190void Timer::startTimer() {
191 assert(!Running && "Cannot start a running timer");
192 Running = Triggered = true;
193 Signposts->startInterval(O: this, Name: getName());
194 StartTime = TimeRecord::getCurrentTime(Start: true);
195}
196
197void Timer::stopTimer() {
198 assert(Running && "Cannot stop a paused timer");
199 Running = false;
200 Time += TimeRecord::getCurrentTime(Start: false);
201 Time -= StartTime;
202 Signposts->endInterval(O: this, Name: getName());
203}
204
205void Timer::clear() {
206 Running = Triggered = false;
207 Time = StartTime = TimeRecord();
208}
209
210static void printVal(double Val, double Total, raw_ostream &OS) {
211 if (Total < 1e-7) // Avoid dividing by zero.
212 OS << " ----- ";
213 else
214 OS << format(Fmt: " %7.4f (%5.1f%%)", Vals: Val, Vals: Val*100/Total);
215}
216
217void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
218 if (Total.getUserTime())
219 printVal(Val: getUserTime(), Total: Total.getUserTime(), OS);
220 if (Total.getSystemTime())
221 printVal(Val: getSystemTime(), Total: Total.getSystemTime(), OS);
222 if (Total.getProcessTime())
223 printVal(Val: getProcessTime(), Total: Total.getProcessTime(), OS);
224 printVal(Val: getWallTime(), Total: Total.getWallTime(), OS);
225
226 OS << " ";
227
228 if (Total.getMemUsed())
229 OS << format(Fmt: "%9" PRId64 " ", Vals: (int64_t)getMemUsed());
230 if (Total.getInstructionsExecuted())
231 OS << format(Fmt: "%9" PRId64 " ", Vals: (int64_t)getInstructionsExecuted());
232}
233
234
235//===----------------------------------------------------------------------===//
236// NamedRegionTimer Implementation
237//===----------------------------------------------------------------------===//
238
239namespace {
240
241typedef StringMap<Timer> Name2TimerMap;
242
243class Name2PairMap {
244 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
245public:
246 ~Name2PairMap() {
247 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
248 I = Map.begin(), E = Map.end(); I != E; ++I)
249 delete I->second.first;
250 }
251
252 Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
253 StringRef GroupDescription) {
254 sys::SmartScopedLock<true> L(*TimerLock);
255
256 std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
257
258 if (!GroupEntry.first)
259 GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
260
261 Timer &T = GroupEntry.second[Name];
262 if (!T.isInitialized())
263 T.init(TimerName: Name, TimerDescription: Description, tg&: *GroupEntry.first);
264 return T;
265 }
266};
267
268}
269
270static ManagedStatic<Name2PairMap> NamedGroupedTimers;
271
272NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
273 StringRef GroupName,
274 StringRef GroupDescription, bool Enabled)
275 : TimeRegion(!Enabled ? nullptr
276 : &NamedGroupedTimers->get(Name, Description, GroupName,
277 GroupDescription)) {}
278
279//===----------------------------------------------------------------------===//
280// TimerGroup Implementation
281//===----------------------------------------------------------------------===//
282
283/// This is the global list of TimerGroups, maintained by the TimerGroup
284/// ctor/dtor and is protected by the TimerLock lock.
285static TimerGroup *TimerGroupList = nullptr;
286
287TimerGroup::TimerGroup(StringRef Name, StringRef Description)
288 : Name(Name.begin(), Name.end()),
289 Description(Description.begin(), Description.end()) {
290 // Add the group to TimerGroupList.
291 sys::SmartScopedLock<true> L(*TimerLock);
292 if (TimerGroupList)
293 TimerGroupList->Prev = &Next;
294 Next = TimerGroupList;
295 Prev = &TimerGroupList;
296 TimerGroupList = this;
297}
298
299TimerGroup::TimerGroup(StringRef Name, StringRef Description,
300 const StringMap<TimeRecord> &Records)
301 : TimerGroup(Name, Description) {
302 TimersToPrint.reserve(n: Records.size());
303 for (const auto &P : Records)
304 TimersToPrint.emplace_back(args: P.getValue(), args: std::string(P.getKey()),
305 args: std::string(P.getKey()));
306 assert(TimersToPrint.size() == Records.size() && "Size mismatch");
307}
308
309TimerGroup::~TimerGroup() {
310 // If the timer group is destroyed before the timers it owns, accumulate and
311 // print the timing data.
312 while (FirstTimer)
313 removeTimer(T&: *FirstTimer);
314
315 // Remove the group from the TimerGroupList.
316 sys::SmartScopedLock<true> L(*TimerLock);
317 *Prev = Next;
318 if (Next)
319 Next->Prev = Prev;
320}
321
322
323void TimerGroup::removeTimer(Timer &T) {
324 sys::SmartScopedLock<true> L(*TimerLock);
325
326 // If the timer was started, move its data to TimersToPrint.
327 if (T.hasTriggered())
328 TimersToPrint.emplace_back(args&: T.Time, args&: T.Name, args&: T.Description);
329
330 T.TG = nullptr;
331
332 // Unlink the timer from our list.
333 *T.Prev = T.Next;
334 if (T.Next)
335 T.Next->Prev = T.Prev;
336
337 // Print the report when all timers in this group are destroyed if some of
338 // them were started.
339 if (FirstTimer || TimersToPrint.empty())
340 return;
341
342 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
343 PrintQueuedTimers(OS&: *OutStream);
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 != getDefaultTimerGroup())
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 assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
460 "TimerGroup name should not need quotes");
461 assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
462 "Timer name should not need quotes");
463 constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
464 OS << "\t\"time." << Name << '.' << R.Name << suffix
465 << "\": " << format(Fmt: "%.*e", Vals: max_digits10 - 1, Vals: Value);
466}
467
468const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
469 sys::SmartScopedLock<true> L(*TimerLock);
470
471 prepareToPrintList(ResetTime: false);
472 for (const PrintRecord &R : TimersToPrint) {
473 OS << delim;
474 delim = ",\n";
475
476 const TimeRecord &T = R.Time;
477 printJSONValue(OS, R, suffix: ".wall", Value: T.getWallTime());
478 OS << delim;
479 printJSONValue(OS, R, suffix: ".user", Value: T.getUserTime());
480 OS << delim;
481 printJSONValue(OS, R, suffix: ".sys", Value: T.getSystemTime());
482 if (T.getMemUsed()) {
483 OS << delim;
484 printJSONValue(OS, R, suffix: ".mem", Value: T.getMemUsed());
485 }
486 if (T.getInstructionsExecuted()) {
487 OS << delim;
488 printJSONValue(OS, R, suffix: ".instr", Value: T.getInstructionsExecuted());
489 }
490 }
491 TimersToPrint.clear();
492 return delim;
493}
494
495const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
496 sys::SmartScopedLock<true> L(*TimerLock);
497 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
498 delim = TG->printJSONValues(OS, delim);
499 return delim;
500}
501
502void TimerGroup::constructForStatistics() {
503 (void)getLibSupportInfoOutputFilename();
504 (void)*NamedGroupedTimers;
505}
506
507std::unique_ptr<TimerGroup> TimerGroup::aquireDefaultGroup() {
508 return std::unique_ptr<TimerGroup>(DefaultTimerGroup.claim());
509}
510