1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
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
7 //===----------------------------------------------------------------------===//
9 /// \file Interval Timing implementation.
11 //===----------------------------------------------------------------------===//
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"
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;
37 static std::string &getLibSupportInfoOutputFilename() {
38 return *LibSupportInfoOutputFilename;
41 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
43 /// Allows llvm::Timer to emit signposts when supported.
44 static ManagedStatic<SignpostEmitter> Signposts;
48 TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
49 "tracking (this may be slow)"),
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()));
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.
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.
70 auto Result = std::make_unique<raw_fd_ostream>(
71 OutputFilename, EC, sys::fs::OF_Append | sys::fs::OF_Text);
75 errs() << "Error opening info-output-file '"
76 << OutputFilename << " for appending!\n";
77 return std::make_unique<raw_fd_ostream>(2, false); // stderr.
81 struct CreateDefaultTimerGroup {
83 return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
87 static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
88 static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
90 //===----------------------------------------------------------------------===//
91 // Timer Implementation
92 //===----------------------------------------------------------------------===//
94 void Timer::init(StringRef TimerName, StringRef TimerDescription) {
95 init(TimerName, TimerDescription, *getDefaultTimerGroup());
98 void Timer::init(StringRef TimerName, StringRef TimerDescription,
100 assert(!TG && "Timer already initialized");
101 Name.assign(TimerName.begin(), TimerName.end());
102 Description.assign(TimerDescription.begin(), TimerDescription.end());
103 Running = Triggered = false;
109 if (!TG) return; // Never initialized, or already cleared.
110 TG->removeTimer(*this);
113 static inline size_t getMemUsage() {
114 if (!TrackSpace) return 0;
115 return sys::Process::GetMallocUsage();
118 TimeRecord TimeRecord::getCurrentTime(bool Start) {
119 using Seconds = std::chrono::duration<double, std::ratio<1>>;
121 sys::TimePoint<> now;
122 std::chrono::nanoseconds user, sys;
125 Result.MemUsed = getMemUsage();
126 sys::Process::GetTimeUsage(now, user, sys);
128 sys::Process::GetTimeUsage(now, user, sys);
129 Result.MemUsed = getMemUsage();
132 Result.WallTime = Seconds(now.time_since_epoch()).count();
133 Result.UserTime = Seconds(user).count();
134 Result.SystemTime = Seconds(sys).count();
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);
145 void Timer::stopTimer() {
146 assert(Running && "Cannot stop a paused timer");
148 Time += TimeRecord::getCurrentTime(false);
150 Signposts->endTimerInterval(this);
153 void Timer::clear() {
154 Running = Triggered = false;
155 Time = StartTime = TimeRecord();
158 static void printVal(double Val, double Total, raw_ostream &OS) {
159 if (Total < 1e-7) // Avoid dividing by zero.
162 OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);
165 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);
176 if (Total.getMemUsed())
177 OS << format("%9" PRId64 " ", (int64_t)getMemUsed());
181 //===----------------------------------------------------------------------===//
182 // NamedRegionTimer Implementation
183 //===----------------------------------------------------------------------===//
187 typedef StringMap<Timer> Name2TimerMap;
190 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
193 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
194 I = Map.begin(), E = Map.end(); I != E; ++I)
195 delete I->second.first;
198 Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
199 StringRef GroupDescription) {
200 sys::SmartScopedLock<true> L(*TimerLock);
202 std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
204 if (!GroupEntry.first)
205 GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
207 Timer &T = GroupEntry.second[Name];
208 if (!T.isInitialized())
209 T.init(Name, Description, *GroupEntry.first);
216 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
218 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
220 StringRef GroupDescription, bool Enabled)
221 : TimeRegion(!Enabled ? nullptr
222 : &NamedGroupedTimers->get(Name, Description, GroupName,
223 GroupDescription)) {}
225 //===----------------------------------------------------------------------===//
226 // TimerGroup Implementation
227 //===----------------------------------------------------------------------===//
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;
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);
239 TimerGroupList->Prev = &Next;
240 Next = TimerGroupList;
241 Prev = &TimerGroupList;
242 TimerGroupList = this;
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");
254 TimerGroup::~TimerGroup() {
255 // If the timer group is destroyed before the timers it owns, accumulate and
256 // print the timing data.
258 removeTimer(*FirstTimer);
260 // Remove the group from the TimerGroupList.
261 sys::SmartScopedLock<true> L(*TimerLock);
268 void TimerGroup::removeTimer(Timer &T) {
269 sys::SmartScopedLock<true> L(*TimerLock);
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);
277 // Unlink the timer from our list.
280 T.Next->Prev = T.Prev;
282 // Print the report when all timers in this group are destroyed if some of
283 // them were started.
284 if (FirstTimer || TimersToPrint.empty())
287 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
288 PrintQueuedTimers(*OutStream);
291 void TimerGroup::addTimer(Timer &T) {
292 sys::SmartScopedLock<true> L(*TimerLock);
294 // Add the timer to our list.
296 FirstTimer->Prev = &T.Next;
298 T.Prev = &FirstTimer;
302 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
303 // Sort the timers in descending order by amount of time taken.
304 llvm::sort(TimersToPrint);
307 for (const PrintRecord &Record : TimersToPrint)
308 Total += Record.Time;
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";
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());
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())
335 OS << " --- Name ---\n";
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';
344 Total.print(Total, OS);
348 TimersToPrint.clear();
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();
359 TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
369 void TimerGroup::print(raw_ostream &OS, bool ResetAfterPrint) {
371 // After preparing the timers we can free the lock
372 sys::SmartScopedLock<true> L(*TimerLock);
373 prepareToPrintList(ResetAfterPrint);
376 // If any timers were started, print the group.
377 if (!TimersToPrint.empty())
378 PrintQueuedTimers(OS);
381 void TimerGroup::clear() {
382 sys::SmartScopedLock<true> L(*TimerLock);
383 for (Timer *T = FirstTimer; T; T = T->Next)
387 void TimerGroup::printAll(raw_ostream &OS) {
388 sys::SmartScopedLock<true> L(*TimerLock);
390 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
394 void TimerGroup::clearAll() {
395 sys::SmartScopedLock<true> L(*TimerLock);
396 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
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);
411 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
412 sys::SmartScopedLock<true> L(*TimerLock);
414 prepareToPrintList(false);
415 for (const PrintRecord &R : TimersToPrint) {
419 const TimeRecord &T = R.Time;
420 printJSONValue(OS, R, ".wall", T.getWallTime());
422 printJSONValue(OS, R, ".user", T.getUserTime());
424 printJSONValue(OS, R, ".sys", T.getSystemTime());
425 if (T.getMemUsed()) {
427 printJSONValue(OS, R, ".mem", T.getMemUsed());
430 TimersToPrint.clear();
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);
441 void TimerGroup::ConstructTimerLists() {
442 (void)*NamedGroupedTimers;