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