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/raw_ostream.h"
24 #include "llvm/Support/YAMLTraits.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 static TimerGroup *DefaultTimerGroup = nullptr;
77 static TimerGroup *getDefaultTimerGroup() {
78 TimerGroup *tmp = DefaultTimerGroup;
82 sys::SmartScopedLock<true> Lock(*TimerLock);
83 tmp = DefaultTimerGroup;
85 tmp = new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
87 DefaultTimerGroup = tmp;
93 //===----------------------------------------------------------------------===//
94 // Timer Implementation
95 //===----------------------------------------------------------------------===//
97 void Timer::init(StringRef Name, StringRef Description) {
98 init(Name, Description, *getDefaultTimerGroup());
101 void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
102 assert(!TG && "Timer already initialized");
103 this->Name.assign(Name.begin(), Name.end());
104 this->Description.assign(Description.begin(), Description.end());
105 Running = Triggered = false;
111 if (!TG) return; // Never initialized, or already cleared.
112 TG->removeTimer(*this);
115 static inline size_t getMemUsage() {
116 if (!TrackSpace) return 0;
117 return sys::Process::GetMallocUsage();
120 TimeRecord TimeRecord::getCurrentTime(bool Start) {
121 using Seconds = std::chrono::duration<double, std::ratio<1>>;
123 sys::TimePoint<> now;
124 std::chrono::nanoseconds user, sys;
127 Result.MemUsed = getMemUsage();
128 sys::Process::GetTimeUsage(now, user, sys);
130 sys::Process::GetTimeUsage(now, user, sys);
131 Result.MemUsed = getMemUsage();
134 Result.WallTime = Seconds(now.time_since_epoch()).count();
135 Result.UserTime = Seconds(user).count();
136 Result.SystemTime = Seconds(sys).count();
140 void Timer::startTimer() {
141 assert(!Running && "Cannot start a running timer");
142 Running = Triggered = true;
143 StartTime = TimeRecord::getCurrentTime(true);
146 void Timer::stopTimer() {
147 assert(Running && "Cannot stop a paused timer");
149 Time += TimeRecord::getCurrentTime(false);
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() {
246 // If the timer group is destroyed before the timers it owns, accumulate and
247 // print the timing data.
249 removeTimer(*FirstTimer);
251 // Remove the group from the TimerGroupList.
252 sys::SmartScopedLock<true> L(*TimerLock);
259 void TimerGroup::removeTimer(Timer &T) {
260 sys::SmartScopedLock<true> L(*TimerLock);
262 // If the timer was started, move its data to TimersToPrint.
263 if (T.hasTriggered())
264 TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
268 // Unlink the timer from our list.
271 T.Next->Prev = T.Prev;
273 // Print the report when all timers in this group are destroyed if some of
274 // them were started.
275 if (FirstTimer || TimersToPrint.empty())
278 std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
279 PrintQueuedTimers(*OutStream);
282 void TimerGroup::addTimer(Timer &T) {
283 sys::SmartScopedLock<true> L(*TimerLock);
285 // Add the timer to our list.
287 FirstTimer->Prev = &T.Next;
289 T.Prev = &FirstTimer;
293 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
294 // Sort the timers in descending order by amount of time taken.
295 std::sort(TimersToPrint.begin(), TimersToPrint.end());
298 for (const PrintRecord &Record : TimersToPrint)
299 Total += Record.Time;
301 // Print out timing header.
302 OS << "===" << std::string(73, '-') << "===\n";
303 // Figure out how many spaces to indent TimerGroup name.
304 unsigned Padding = (80-Description.length())/2;
305 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers
306 OS.indent(Padding) << Description << '\n';
307 OS << "===" << std::string(73, '-') << "===\n";
309 // If this is not an collection of ungrouped times, print the total time.
310 // Ungrouped timers don't really make sense to add up. We still print the
311 // TOTAL line to make the percentages make sense.
312 if (this != DefaultTimerGroup)
313 OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
314 Total.getProcessTime(), Total.getWallTime());
317 if (Total.getUserTime())
318 OS << " ---User Time---";
319 if (Total.getSystemTime())
320 OS << " --System Time--";
321 if (Total.getProcessTime())
322 OS << " --User+System--";
323 OS << " ---Wall Time---";
324 if (Total.getMemUsed())
326 OS << " --- Name ---\n";
328 // Loop through all of the timing data, printing it out.
329 for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
330 TimersToPrint.rend())) {
331 Record.Time.print(Total, OS);
332 OS << Record.Description << '\n';
335 Total.print(Total, OS);
339 TimersToPrint.clear();
342 void TimerGroup::prepareToPrintList() {
343 // See if any of our timers were started, if so add them to TimersToPrint and
345 for (Timer *T = FirstTimer; T; T = T->Next) {
346 if (!T->hasTriggered()) continue;
347 TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
349 // Clear out the time.
354 void TimerGroup::print(raw_ostream &OS) {
355 sys::SmartScopedLock<true> L(*TimerLock);
357 prepareToPrintList();
359 // If any timers were started, print the group.
360 if (!TimersToPrint.empty())
361 PrintQueuedTimers(OS);
364 void TimerGroup::printAll(raw_ostream &OS) {
365 sys::SmartScopedLock<true> L(*TimerLock);
367 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
371 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
372 const char *suffix, double Value) {
373 assert(!yaml::needsQuotes(Name) && "TimerGroup name needs no quotes");
374 assert(!yaml::needsQuotes(R.Name) && "Timer name needs no quotes");
375 OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value;
378 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
379 prepareToPrintList();
380 for (const PrintRecord &R : TimersToPrint) {
384 const TimeRecord &T = R.Time;
385 printJSONValue(OS, R, ".wall", T.getWallTime());
387 printJSONValue(OS, R, ".user", T.getUserTime());
389 printJSONValue(OS, R, ".sys", T.getSystemTime());
391 TimersToPrint.clear();
395 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
396 sys::SmartScopedLock<true> L(*TimerLock);
397 for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
398 delim = TG->printJSONValues(OS, delim);
402 void TimerGroup::ConstructTimerLists() {
403 (void)*NamedGroupedTimers;