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