LLVM  9.0.0svn
Timer.cpp
Go to the documentation of this file.
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"
18 #include "llvm/Support/Format.h"
20 #include "llvm/Support/Mutex.h"
21 #include "llvm/Support/Process.h"
24 #include <limits>
25 
26 using namespace llvm;
27 
28 // This ugly hack is brought to you courtesy of constructor/destructor ordering
29 // being unspecified by C++. Basically the problem is that a Statistic object
30 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
31 // (below), which calls this function. LibSupportInfoOutputFilename used to be
32 // a global variable, but sometimes it would get destroyed before the Statistic,
33 // causing havoc to ensue. We "fix" this by creating the string the first time
34 // it is needed and never destroying it.
36 static std::string &getLibSupportInfoOutputFilename() {
38 }
39 
41 
42 namespace {
43  static cl::opt<bool>
44  TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
45  "tracking (this may be slow)"),
46  cl::Hidden);
47 
49  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
50  cl::desc("File to append -stats and -timer output to"),
52 }
53 
54 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
55  const std::string &OutputFilename = getLibSupportInfoOutputFilename();
56  if (OutputFilename.empty())
57  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
58  if (OutputFilename == "-")
59  return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
60 
61  // Append mode is used because the info output file is opened and closed
62  // each time -stats or -time-passes wants to print output to it. To
63  // compensate for this, the test-suite Makefiles have code to delete the
64  // info output file before running commands which write to it.
65  std::error_code EC;
66  auto Result = llvm::make_unique<raw_fd_ostream>(
68  if (!EC)
69  return Result;
70 
71  errs() << "Error opening info-output-file '"
72  << OutputFilename << " for appending!\n";
73  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
74 }
75 
76 namespace {
77 struct CreateDefaultTimerGroup {
78  static void *call() {
79  return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
80  }
81 };
82 } // namespace
85 
86 //===----------------------------------------------------------------------===//
87 // Timer Implementation
88 //===----------------------------------------------------------------------===//
89 
90 void Timer::init(StringRef Name, StringRef Description) {
91  init(Name, Description, *getDefaultTimerGroup());
92 }
93 
94 void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
95  assert(!TG && "Timer already initialized");
96  this->Name.assign(Name.begin(), Name.end());
97  this->Description.assign(Description.begin(), Description.end());
98  Running = Triggered = false;
99  TG = &tg;
100  TG->addTimer(*this);
101 }
102 
104  if (!TG) return; // Never initialized, or already cleared.
105  TG->removeTimer(*this);
106 }
107 
108 static inline size_t getMemUsage() {
109  if (!TrackSpace) return 0;
111 }
112 
114  using Seconds = std::chrono::duration<double, std::ratio<1>>;
115  TimeRecord Result;
117  std::chrono::nanoseconds user, sys;
118 
119  if (Start) {
120  Result.MemUsed = getMemUsage();
121  sys::Process::GetTimeUsage(now, user, sys);
122  } else {
123  sys::Process::GetTimeUsage(now, user, sys);
124  Result.MemUsed = getMemUsage();
125  }
126 
127  Result.WallTime = Seconds(now.time_since_epoch()).count();
128  Result.UserTime = Seconds(user).count();
129  Result.SystemTime = Seconds(sys).count();
130  return Result;
131 }
132 
134  assert(!Running && "Cannot start a running timer");
135  Running = Triggered = true;
136  StartTime = TimeRecord::getCurrentTime(true);
137 }
138 
140  assert(Running && "Cannot stop a paused timer");
141  Running = false;
142  Time += TimeRecord::getCurrentTime(false);
143  Time -= StartTime;
144 }
145 
146 void Timer::clear() {
147  Running = Triggered = false;
148  Time = StartTime = TimeRecord();
149 }
150 
151 static void printVal(double Val, double Total, raw_ostream &OS) {
152  if (Total < 1e-7) // Avoid dividing by zero.
153  OS << " ----- ";
154  else
155  OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);
156 }
157 
158 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
159  if (Total.getUserTime())
160  printVal(getUserTime(), Total.getUserTime(), OS);
161  if (Total.getSystemTime())
162  printVal(getSystemTime(), Total.getSystemTime(), OS);
163  if (Total.getProcessTime())
164  printVal(getProcessTime(), Total.getProcessTime(), OS);
165  printVal(getWallTime(), Total.getWallTime(), OS);
166 
167  OS << " ";
168 
169  if (Total.getMemUsed())
170  OS << format("%9" PRId64 " ", (int64_t)getMemUsed());
171 }
172 
173 
174 //===----------------------------------------------------------------------===//
175 // NamedRegionTimer Implementation
176 //===----------------------------------------------------------------------===//
177 
178 namespace {
179 
180 typedef StringMap<Timer> Name2TimerMap;
181 
182 class Name2PairMap {
184 public:
185  ~Name2PairMap() {
186  for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
187  I = Map.begin(), E = Map.end(); I != E; ++I)
188  delete I->second.first;
189  }
190 
191  Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
192  StringRef GroupDescription) {
193  sys::SmartScopedLock<true> L(*TimerLock);
194 
195  std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
196 
197  if (!GroupEntry.first)
198  GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
199 
200  Timer &T = GroupEntry.second[Name];
201  if (!T.isInitialized())
202  T.init(Name, Description, *GroupEntry.first);
203  return T;
204  }
205 };
206 
207 }
208 
210 
212  StringRef GroupName,
213  StringRef GroupDescription, bool Enabled)
214  : TimeRegion(!Enabled ? nullptr
215  : &NamedGroupedTimers->get(Name, Description, GroupName,
216  GroupDescription)) {}
217 
218 //===----------------------------------------------------------------------===//
219 // TimerGroup Implementation
220 //===----------------------------------------------------------------------===//
221 
222 /// This is the global list of TimerGroups, maintained by the TimerGroup
223 /// ctor/dtor and is protected by the TimerLock lock.
224 static TimerGroup *TimerGroupList = nullptr;
225 
226 TimerGroup::TimerGroup(StringRef Name, StringRef Description)
227  : Name(Name.begin(), Name.end()),
228  Description(Description.begin(), Description.end()) {
229  // Add the group to TimerGroupList.
230  sys::SmartScopedLock<true> L(*TimerLock);
231  if (TimerGroupList)
232  TimerGroupList->Prev = &Next;
233  Next = TimerGroupList;
234  Prev = &TimerGroupList;
235  TimerGroupList = this;
236 }
237 
238 TimerGroup::TimerGroup(StringRef Name, StringRef Description,
239  const StringMap<TimeRecord> &Records)
240  : TimerGroup(Name, Description) {
241  TimersToPrint.reserve(Records.size());
242  for (const auto &P : Records)
243  TimersToPrint.emplace_back(P.getValue(), P.getKey(), P.getKey());
244  assert(TimersToPrint.size() == Records.size() && "Size mismatch");
245 }
246 
248  // If the timer group is destroyed before the timers it owns, accumulate and
249  // print the timing data.
250  while (FirstTimer)
251  removeTimer(*FirstTimer);
252 
253  // Remove the group from the TimerGroupList.
254  sys::SmartScopedLock<true> L(*TimerLock);
255  *Prev = Next;
256  if (Next)
257  Next->Prev = Prev;
258 }
259 
260 
261 void TimerGroup::removeTimer(Timer &T) {
262  sys::SmartScopedLock<true> L(*TimerLock);
263 
264  // If the timer was started, move its data to TimersToPrint.
265  if (T.hasTriggered())
266  TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
267 
268  T.TG = nullptr;
269 
270  // Unlink the timer from our list.
271  *T.Prev = T.Next;
272  if (T.Next)
273  T.Next->Prev = T.Prev;
274 
275  // Print the report when all timers in this group are destroyed if some of
276  // them were started.
277  if (FirstTimer || TimersToPrint.empty())
278  return;
279 
280  std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
281  PrintQueuedTimers(*OutStream);
282 }
283 
284 void TimerGroup::addTimer(Timer &T) {
285  sys::SmartScopedLock<true> L(*TimerLock);
286 
287  // Add the timer to our list.
288  if (FirstTimer)
289  FirstTimer->Prev = &T.Next;
290  T.Next = FirstTimer;
291  T.Prev = &FirstTimer;
292  FirstTimer = &T;
293 }
294 
295 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
296  // Sort the timers in descending order by amount of time taken.
297  llvm::sort(TimersToPrint);
298 
299  TimeRecord Total;
300  for (const PrintRecord &Record : TimersToPrint)
301  Total += Record.Time;
302 
303  // Print out timing header.
304  OS << "===" << std::string(73, '-') << "===\n";
305  // Figure out how many spaces to indent TimerGroup name.
306  unsigned Padding = (80-Description.length())/2;
307  if (Padding > 80) Padding = 0; // Don't allow "negative" numbers
308  OS.indent(Padding) << Description << '\n';
309  OS << "===" << std::string(73, '-') << "===\n";
310 
311  // If this is not an collection of ungrouped times, print the total time.
312  // Ungrouped timers don't really make sense to add up. We still print the
313  // TOTAL line to make the percentages make sense.
314  if (this != getDefaultTimerGroup())
315  OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
316  Total.getProcessTime(), Total.getWallTime());
317  OS << '\n';
318 
319  if (Total.getUserTime())
320  OS << " ---User Time---";
321  if (Total.getSystemTime())
322  OS << " --System Time--";
323  if (Total.getProcessTime())
324  OS << " --User+System--";
325  OS << " ---Wall Time---";
326  if (Total.getMemUsed())
327  OS << " ---Mem---";
328  OS << " --- Name ---\n";
329 
330  // Loop through all of the timing data, printing it out.
331  for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
332  TimersToPrint.rend())) {
333  Record.Time.print(Total, OS);
334  OS << Record.Description << '\n';
335  }
336 
337  Total.print(Total, OS);
338  OS << "Total\n\n";
339  OS.flush();
340 
341  TimersToPrint.clear();
342 }
343 
344 void TimerGroup::prepareToPrintList() {
345  // See if any of our timers were started, if so add them to TimersToPrint.
346  for (Timer *T = FirstTimer; T; T = T->Next) {
347  if (!T->hasTriggered()) continue;
348  bool WasRunning = T->isRunning();
349  if (WasRunning)
350  T->stopTimer();
351 
352  TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
353 
354  if (WasRunning)
355  T->startTimer();
356  }
357 }
358 
360  sys::SmartScopedLock<true> L(*TimerLock);
361 
362  prepareToPrintList();
363 
364  // If any timers were started, print the group.
365  if (!TimersToPrint.empty())
366  PrintQueuedTimers(OS);
367 }
368 
370  sys::SmartScopedLock<true> L(*TimerLock);
371  for (Timer *T = FirstTimer; T; T = T->Next)
372  T->clear();
373 }
374 
376  sys::SmartScopedLock<true> L(*TimerLock);
377 
378  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
379  TG->print(OS);
380 }
381 
383  sys::SmartScopedLock<true> L(*TimerLock);
384  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
385  TG->clear();
386 }
387 
388 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
389  const char *suffix, double Value) {
390  assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
391  "TimerGroup name should not need quotes");
392  assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
393  "Timer name should not need quotes");
394  constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
395  OS << "\t\"time." << Name << '.' << R.Name << suffix
396  << "\": " << format("%.*e", max_digits10 - 1, Value);
397 }
398 
399 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
400  sys::SmartScopedLock<true> L(*TimerLock);
401 
402  prepareToPrintList();
403  for (const PrintRecord &R : TimersToPrint) {
404  OS << delim;
405  delim = ",\n";
406 
407  const TimeRecord &T = R.Time;
408  printJSONValue(OS, R, ".wall", T.getWallTime());
409  OS << delim;
410  printJSONValue(OS, R, ".user", T.getUserTime());
411  OS << delim;
412  printJSONValue(OS, R, ".sys", T.getSystemTime());
413  if (T.getMemUsed()) {
414  OS << delim;
415  printJSONValue(OS, R, ".mem", T.getMemUsed());
416  }
417  }
418  TimersToPrint.clear();
419  return delim;
420 }
421 
422 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
423  sys::SmartScopedLock<true> L(*TimerLock);
424  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
425  delim = TG->printJSONValues(OS, delim);
426  return delim;
427 }
428 
430  (void)*NamedGroupedTimers;
431 }
const NoneType None
Definition: None.h:23
const_iterator end(StringRef path)
Get end iterator over path.
Definition: Path.cpp:258
raw_ostream & errs()
This returns a reference to a raw_ostream for standard error.
static TimeRecord getCurrentTime(bool Start=true)
Get the current time and memory usage.
Definition: Timer.cpp:113
const_iterator begin(StringRef path, Style style=Style::native)
Get begin iterator over path.
Definition: Path.cpp:249
const char * printJSONValues(raw_ostream &OS, const char *delim)
Definition: Timer.cpp:399
void init(StringRef Name, StringRef Description)
Definition: Timer.cpp:90
This class represents lattice values for constants.
Definition: AllocatorList.h:23
void print(raw_ostream &OS) const
amdgpu Simplify well known AMD library false FunctionCallee Value const Twine & Name
void stopTimer()
Stop the timer.
Definition: Timer.cpp:139
format_object< Ts... > format(const char *Fmt, const Ts &... Vals)
These are helper functions used to produce formatted output.
Definition: Format.h:123
raw_ostream & indent(unsigned NumSpaces)
indent - Insert &#39;NumSpaces&#39; spaces.
bool isRunning() const
Check if the timer is currently running.
Definition: Timer.h:113
The TimeRegion class is used as a helper class to call the startTimer() and stopTimer() methods of th...
Definition: Timer.h:140
unsigned size() const
Definition: StringMap.h:111
double getUserTime() const
Definition: Timer.h:41
static cl::opt< std::string > OutputFilename("o", cl::desc("Output filename"), cl::value_desc("filename"), cl::init("-"))
This class is used to track the amount of time spent between invocations of its startTimer()/stopTime...
Definition: Timer.h:76
#define T
void print(const TimeRecord &Total, raw_ostream &OS) const
Print the current time record to OS, with a breakdown showing contributions to the Total time record...
Definition: Timer.cpp:158
static void printVal(double Val, double Total, raw_ostream &OS)
Definition: Timer.cpp:151
std::unique_ptr< raw_fd_ostream > CreateInfoOutputFile()
Return a file stream to print our output on.
Definition: Timer.cpp:54
auto count(R &&Range, const E &Element) -> typename std::iterator_traits< decltype(adl_begin(Range))>::difference_type
Wrapper function around std::count to count the number of times an element Element occurs in the give...
Definition: STLExtras.h:1251
static TimerGroup * TimerGroupList
This is the global list of TimerGroups, maintained by the TimerGroup ctor/dtor and is protected by th...
Definition: Timer.cpp:224
#define P(N)
initializer< Ty > init(const Ty &Val)
Definition: CommandLine.h:422
static GCRegistry::Add< CoreCLRGC > E("coreclr", "CoreCLR-compatible GC")
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
void clear()
Clear the timer state.
Definition: Timer.cpp:146
static ManagedStatic< std::string > LibSupportInfoOutputFilename
Definition: Timer.cpp:35
static ManagedStatic< Name2PairMap > NamedGroupedTimers
Definition: Timer.cpp:209
static size_t GetMallocUsage()
Return process memory usage.
void print(raw_ostream &OS)
Print any started timers in this group.
Definition: Timer.cpp:359
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1115
ssize_t getMemUsed() const
Definition: Timer.h:44
iterator_range< T > make_range(T x, T y)
Convenience function for iterating over sub-ranges.
double getProcessTime() const
Definition: Timer.h:40
static TimerGroup * getDefaultTimerGroup()
Definition: Timer.cpp:84
double getSystemTime() const
Definition: Timer.h:42
bool isInitialized() const
Definition: Timer.h:110
void startTimer()
Start the timer running.
Definition: Timer.cpp:133
static bool Enabled
Definition: Statistic.cpp:50
static void clearAll()
Clear out all timers.
Definition: Timer.cpp:382
StringMap - This is an unconventional map that is specialized for handling keys that are "strings"...
Definition: StringMap.h:219
static std::string & getLibSupportInfoOutputFilename()
Definition: Timer.cpp:36
void clear()
Clear all timers in this group.
Definition: Timer.cpp:369
iterator begin() const
Definition: StringRef.h:101
static ManagedStatic< TimerGroup, CreateDefaultTimerGroup > DefaultTimerGroup
Definition: Timer.cpp:83
static const char * printAllJSONValues(raw_ostream &OS, const char *delim)
Prints all timers as JSON key/value pairs.
Definition: Timer.cpp:422
Provides a library for accessing information about this process and other processes on the operating ...
iterator begin()
Definition: StringMap.h:314
#define I(x, y, z)
Definition: MD5.cpp:58
The TimerGroup class is used to group together related timers into a single report that is printed wh...
Definition: Timer.h:170
double getWallTime() const
Definition: Timer.h:43
static void GetTimeUsage(TimePoint<> &elapsed, std::chrono::nanoseconds &user_time, std::chrono::nanoseconds &sys_time)
This static function will set user_time to the amount of CPU time spent in user (non-kernel) mode and...
NamedRegionTimer(StringRef Name, StringRef Description, StringRef GroupName, StringRef GroupDescription, bool Enabled=true)
Definition: Timer.cpp:211
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
static void ConstructTimerLists()
Ensure global timer group lists are initialized.
Definition: Timer.cpp:429
LLVM Value Representation.
Definition: Value.h:72
static void printAll(raw_ostream &OS)
This static method prints all timers.
Definition: Timer.cpp:375
This class implements an extremely fast bulk output stream that can only output to a stream...
Definition: raw_ostream.h:45
static size_t getMemUsage()
Definition: Timer.cpp:108
StringRef - Represent a constant reference to a string, i.e.
Definition: StringRef.h:48
ManagedStatic - This transparently changes the behavior of global statics to be lazily constructed on...
Definition: ManagedStatic.h:60
iterator end() const
Definition: StringRef.h:103
LocationClass< Ty > location(Ty &L)
Definition: CommandLine.h:438
iterator end()
Definition: StringMap.h:317
static ManagedStatic< sys::SmartMutex< true > > TimerLock
Definition: Timer.cpp:40
bool hasTriggered() const
Check if startTimer() has ever been called on this timer.
Definition: Timer.h:116
std::chrono::time_point< std::chrono::system_clock, D > TimePoint
A time point on the system clock.
Definition: Chrono.h:33