1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
3 // The LLVM Compiler Infrastructure
5 // This file is distributed under the University of Illinois Open Source
6 // License. See LICENSE.TXT for details.
8 //===----------------------------------------------------------------------===//
10 /// \file Interval Timing implementation.
12 //===----------------------------------------------------------------------===//
14 #include "llvm/Support/Timer.h"
15 #include "llvm/ADT/Statistic.h"
16 #include "llvm/ADT/StringMap.h"
17 #include "llvm/Support/CommandLine.h"
18 #include "llvm/Support/FileSystem.h"
19 #include "llvm/Support/Format.h"
20 #include "llvm/Support/ManagedStatic.h"
21 #include "llvm/Support/Mutex.h"
22 #include "llvm/Support/Process.h"
23 #include "llvm/Support/YAMLTraits.h"
24 #include "llvm/Support/raw_ostream.h"
27 // This ugly hack is brought to you courtesy of constructor/destructor ordering
28 // being unspecified by C++. Basically the problem is that a Statistic object
29 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
30 // (below), which calls this function. LibSupportInfoOutputFilename used to be
31 // a global variable, but sometimes it would get destroyed before the Statistic,
32 // causing havoc to ensue. We "fix" this by creating the string the first time
33 // it is needed and never destroying it.
34 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
35 static std::string &getLibSupportInfoOutputFilename() {
36 return *LibSupportInfoOutputFilename;
39 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
43 TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
44 "tracking (this may be slow)"),
47 static cl::opt<std::string, true>
48 InfoOutputFilename("info-output-file", cl::value_desc("filename"),
49 cl::desc("File to append -stats and -timer output to"),
50 cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
53 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
54 const std::string &OutputFilename = getLibSupportInfoOutputFilename();
55 if (OutputFilename.empty())
56 return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
57 if (OutputFilename == "-")
58 return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
60 // Append mode is used because the info output file is opened and closed
61 // each time -stats or -time-passes wants to print output to it. To
62 // compensate for this, the test-suite Makefiles have code to delete the
63 // info output file before running commands which write to it.
65 auto Result = llvm::make_unique<raw_fd_ostream>(
66 OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
70 errs() << "Error opening info-output-file '"
71 << OutputFilename << " for appending!\n";
72 return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
76 struct CreateDefaultTimerGroup {
78 return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
82 static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
83 static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
85 //===----------------------------------------------------------------------===//
86 // Timer Implementation
87 //===----------------------------------------------------------------------===//
89 void Timer::init(StringRef Name, StringRef Description) {
90 init(Name, Description, *getDefaultTimerGroup());
93 void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
94 assert(!TG && "Timer already initialized");
95 this->Name.assign(Name.begin(), Name.end());
96 this->Description.assign(Description.begin(), Description.end());
97 Running = Triggered = false;
103 if (!TG) return; // Never initialized, or already cleared.
104 TG->removeTimer(*this);
107 static inline size_t getMemUsage() {
108 if (!TrackSpace) return 0;
109 return sys::Process::GetMallocUsage();
112 TimeRecord TimeRecord::getCurrentTime(bool Start) {
113 using Seconds = std::chrono::duration<double, std::ratio<1>>;
115 sys::TimePoint<> now;
116 std::chrono::nanoseconds user, sys;
119 Result.MemUsed = getMemUsage();
120 sys::Process::GetTimeUsage(now, user, sys);
122 sys::Process::GetTimeUsage(now, user, sys);
123 Result.MemUsed = getMemUsage();
126 Result.WallTime = Seconds(now.time_since_epoch()).count();
127 Result.UserTime = Seconds(user).count();
128 Result.SystemTime = Seconds(sys).count();
132 void Timer::startTimer() {
133 assert(!Running && "Cannot start a running timer");
134 Running = Triggered = true;
135 StartTime = TimeRecord::getCurrentTime(true);
138 void Timer::stopTimer() {
139 assert(Running && "Cannot stop a paused timer");
141 Time += TimeRecord::getCurrentTime(false);
145 void Timer::clear() {
146 Running = Triggered = false;
147 Time = StartTime = TimeRecord();
150 static void printVal(double Val, double Total, raw_ostream &OS) {
151 if (Total < 1e-7) // Avoid dividing by zero.
154 OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);
157 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
158 if (Total.getUserTime())
159 printVal(getUserTime(), Total.getUserTime(), OS);
160 if (Total.getSystemTime())
161 printVal(getSystemTime(), Total.getSystemTime(), OS);
162 if (Total.getProcessTime())
163 printVal(getProcessTime(), Total.getProcessTime(), OS);
164 printVal(getWallTime(), Total.getWallTime(), OS);
168 if (Total.getMemUsed())
169 OS << format("%9" PRId64 " ", (int64_t)getMemUsed());
173 //===----------------------------------------------------------------------===//
174 // NamedRegionTimer Implementation
175 //===----------------------------------------------------------------------===//
179 typedef StringMap<Timer> Name2TimerMap;
182 StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
185 for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
186 I = Map.begin(), E = Map.end(); I != E; ++I)
187 delete I->second.first;
190 Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
191 StringRef GroupDescription) {
192 sys::SmartScopedLock<true> L(*TimerLock);
194 std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
196 if (!GroupEntry.first)
197 GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
199 Timer &T = GroupEntry.second[Name];
200 if (!T.isInitialized())
201 T.init(Name, Description, *GroupEntry.first);
208 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
210 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
212 StringRef GroupDescription, bool Enabled)
213 : TimeRegion(!Enabled ? nullptr
214 : &NamedGroupedTimers->get(Name, Description, GroupName,
215 GroupDescription)) {}
217 //===----------------------------------------------------------------------===//
218 // TimerGroup Implementation
219 //===----------------------------------------------------------------------===//
221 /// This is the global list of TimerGroups, maintained by the TimerGroup
222 /// ctor/dtor and is protected by the TimerLock lock.
223 static TimerGroup *TimerGroupList = nullptr;
225 TimerGroup::TimerGroup(StringRef Name, StringRef Description)
226 : Name(Name.begin(), Name.end()),
227 Description(Description.begin(), Description.end()) {
228 // Add the group to TimerGroupList.
229 sys::SmartScopedLock<true> L(*TimerLock);
231 TimerGroupList->Prev = &Next;
232 Next = TimerGroupList;
233 Prev = &TimerGroupList;
234 TimerGroupList = this;
237 TimerGroup::~TimerGroup() {
238 // If the timer group is destroyed before the timers it owns, accumulate and
239 // print the timing data.
241 removeTimer(*FirstTimer);
243 // Remove the group from the TimerGroupList.
244 sys::SmartScopedLock<true> L(*TimerLock);
251 void TimerGroup::removeTimer(Timer &T) {
252 sys::SmartScopedLock<true> L(*TimerLock);
254 // If the timer was started, move its data to TimersToPrint.
255 if (T.hasTriggered())
256 TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
260 // Unlink the timer from our list.
263 T.Next->Prev = T.Prev;
265 // Print the report when all timers in this group are destroyed if some of
266 // them were started.
267 if (FirstTimer || TimersToPrint.empty())
270 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
271 PrintQueuedTimers(*OutStream);
274 void TimerGroup::addTimer(Timer &T) {
275 sys::SmartScopedLock<true> L(*TimerLock);
277 // Add the timer to our list.
279 FirstTimer->Prev = &T.Next;
281 T.Prev = &FirstTimer;
285 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
286 // Sort the timers in descending order by amount of time taken.
287 std::sort(TimersToPrint.begin(), TimersToPrint.end());
290 for (const PrintRecord &Record : TimersToPrint)
291 Total += Record.Time;
293 // Print out timing header.
294 OS << "===" << std::string(73, '-') << "===\n";
295 // Figure out how many spaces to indent TimerGroup name.
296 unsigned Padding = (80-Description.length())/2;
297 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers
298 OS.indent(Padding) << Description << '\n';
299 OS << "===" << std::string(73, '-') << "===\n";
301 // If this is not an collection of ungrouped times, print the total time.
302 // Ungrouped timers don't really make sense to add up. We still print the
303 // TOTAL line to make the percentages make sense.
304 if (this != getDefaultTimerGroup())
305 OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
306 Total.getProcessTime(), Total.getWallTime());
309 if (Total.getUserTime())
310 OS << " ---User Time---";
311 if (Total.getSystemTime())
312 OS << " --System Time--";
313 if (Total.getProcessTime())
314 OS << " --User+System--";
315 OS << " ---Wall Time---";
316 if (Total.getMemUsed())
318 OS << " --- Name ---\n";
320 // Loop through all of the timing data, printing it out.
321 for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
322 TimersToPrint.rend())) {
323 Record.Time.print(Total, OS);
324 OS << Record.Description << '\n';
327 Total.print(Total, OS);
331 TimersToPrint.clear();
334 void TimerGroup::prepareToPrintList() {
335 // See if any of our timers were started, if so add them to TimersToPrint and
337 for (Timer *T = FirstTimer; T; T = T->Next) {
338 if (!T->hasTriggered()) continue;
339 TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
341 // Clear out the time.
346 void TimerGroup::print(raw_ostream &OS) {
347 sys::SmartScopedLock<true> L(*TimerLock);
349 prepareToPrintList();
351 // If any timers were started, print the group.
352 if (!TimersToPrint.empty())
353 PrintQueuedTimers(OS);
356 void TimerGroup::printAll(raw_ostream &OS) {
357 sys::SmartScopedLock<true> L(*TimerLock);
359 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
363 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
364 const char *suffix, double Value) {
365 assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
366 "TimerGroup name needs no quotes");
367 assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
368 "Timer name needs no quotes");
369 OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value;
372 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
373 prepareToPrintList();
374 for (const PrintRecord &R : TimersToPrint) {
378 const TimeRecord &T = R.Time;
379 printJSONValue(OS, R, ".wall", T.getWallTime());
381 printJSONValue(OS, R, ".user", T.getUserTime());
383 printJSONValue(OS, R, ".sys", T.getSystemTime());
385 TimersToPrint.clear();
389 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
390 sys::SmartScopedLock<true> L(*TimerLock);
391 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
392 delim = TG->printJSONValues(OS, delim);
396 void TimerGroup::ConstructTimerLists() {
397 (void)*NamedGroupedTimers;