LLVM  6.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 using namespace llvm;
26 
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.
35 static std::string &getLibSupportInfoOutputFilename() {
37 }
38 
40 
41 namespace {
42  static cl::opt<bool>
43  TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
44  "tracking (this may be slow)"),
45  cl::Hidden);
46 
48  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
49  cl::desc("File to append -stats and -timer output to"),
51 }
52 
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.
59 
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.
64  std::error_code EC;
65  auto Result = llvm::make_unique<raw_fd_ostream>(
67  if (!EC)
68  return Result;
69 
70  errs() << "Error opening info-output-file '"
71  << OutputFilename << " for appending!\n";
72  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
73 }
74 
75 namespace {
76 struct CreateDefaultTimerGroup {
77  static void *call() {
78  return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
79  }
80 };
81 } // namespace
84 
85 //===----------------------------------------------------------------------===//
86 // Timer Implementation
87 //===----------------------------------------------------------------------===//
88 
89 void Timer::init(StringRef Name, StringRef Description) {
90  init(Name, Description, *getDefaultTimerGroup());
91 }
92 
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;
98  TG = &tg;
99  TG->addTimer(*this);
100 }
101 
103  if (!TG) return; // Never initialized, or already cleared.
104  TG->removeTimer(*this);
105 }
106 
107 static inline size_t getMemUsage() {
108  if (!TrackSpace) return 0;
110 }
111 
113  using Seconds = std::chrono::duration<double, std::ratio<1>>;
114  TimeRecord Result;
116  std::chrono::nanoseconds user, sys;
117 
118  if (Start) {
119  Result.MemUsed = getMemUsage();
120  sys::Process::GetTimeUsage(now, user, sys);
121  } else {
122  sys::Process::GetTimeUsage(now, user, sys);
123  Result.MemUsed = getMemUsage();
124  }
125 
126  Result.WallTime = Seconds(now.time_since_epoch()).count();
127  Result.UserTime = Seconds(user).count();
128  Result.SystemTime = Seconds(sys).count();
129  return Result;
130 }
131 
133  assert(!Running && "Cannot start a running timer");
134  Running = Triggered = true;
135  StartTime = TimeRecord::getCurrentTime(true);
136 }
137 
139  assert(Running && "Cannot stop a paused timer");
140  Running = false;
141  Time += TimeRecord::getCurrentTime(false);
142  Time -= StartTime;
143 }
144 
145 void Timer::clear() {
146  Running = Triggered = false;
147  Time = StartTime = TimeRecord();
148 }
149 
150 static void printVal(double Val, double Total, raw_ostream &OS) {
151  if (Total < 1e-7) // Avoid dividing by zero.
152  OS << " ----- ";
153  else
154  OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);
155 }
156 
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);
165 
166  OS << " ";
167 
168  if (Total.getMemUsed())
169  OS << format("%9" PRId64 " ", (int64_t)getMemUsed());
170 }
171 
172 
173 //===----------------------------------------------------------------------===//
174 // NamedRegionTimer Implementation
175 //===----------------------------------------------------------------------===//
176 
177 namespace {
178 
179 typedef StringMap<Timer> Name2TimerMap;
180 
181 class Name2PairMap {
183 public:
184  ~Name2PairMap() {
185  for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
186  I = Map.begin(), E = Map.end(); I != E; ++I)
187  delete I->second.first;
188  }
189 
190  Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
191  StringRef GroupDescription) {
192  sys::SmartScopedLock<true> L(*TimerLock);
193 
194  std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
195 
196  if (!GroupEntry.first)
197  GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
198 
199  Timer &T = GroupEntry.second[Name];
200  if (!T.isInitialized())
201  T.init(Name, Description, *GroupEntry.first);
202  return T;
203  }
204 };
205 
206 }
207 
209 
211  StringRef GroupName,
212  StringRef GroupDescription, bool Enabled)
213  : TimeRegion(!Enabled ? nullptr
214  : &NamedGroupedTimers->get(Name, Description, GroupName,
215  GroupDescription)) {}
216 
217 //===----------------------------------------------------------------------===//
218 // TimerGroup Implementation
219 //===----------------------------------------------------------------------===//
220 
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;
224 
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);
230  if (TimerGroupList)
231  TimerGroupList->Prev = &Next;
232  Next = TimerGroupList;
233  Prev = &TimerGroupList;
234  TimerGroupList = this;
235 }
236 
238  // If the timer group is destroyed before the timers it owns, accumulate and
239  // print the timing data.
240  while (FirstTimer)
241  removeTimer(*FirstTimer);
242 
243  // Remove the group from the TimerGroupList.
244  sys::SmartScopedLock<true> L(*TimerLock);
245  *Prev = Next;
246  if (Next)
247  Next->Prev = Prev;
248 }
249 
250 
251 void TimerGroup::removeTimer(Timer &T) {
252  sys::SmartScopedLock<true> L(*TimerLock);
253 
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);
257 
258  T.TG = nullptr;
259 
260  // Unlink the timer from our list.
261  *T.Prev = T.Next;
262  if (T.Next)
263  T.Next->Prev = T.Prev;
264 
265  // Print the report when all timers in this group are destroyed if some of
266  // them were started.
267  if (FirstTimer || TimersToPrint.empty())
268  return;
269 
270  std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
271  PrintQueuedTimers(*OutStream);
272 }
273 
274 void TimerGroup::addTimer(Timer &T) {
275  sys::SmartScopedLock<true> L(*TimerLock);
276 
277  // Add the timer to our list.
278  if (FirstTimer)
279  FirstTimer->Prev = &T.Next;
280  T.Next = FirstTimer;
281  T.Prev = &FirstTimer;
282  FirstTimer = &T;
283 }
284 
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());
288 
289  TimeRecord Total;
290  for (const PrintRecord &Record : TimersToPrint)
291  Total += Record.Time;
292 
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";
300 
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());
307  OS << '\n';
308 
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())
317  OS << " ---Mem---";
318  OS << " --- Name ---\n";
319 
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';
325  }
326 
327  Total.print(Total, OS);
328  OS << "Total\n\n";
329  OS.flush();
330 
331  TimersToPrint.clear();
332 }
333 
334 void TimerGroup::prepareToPrintList() {
335  // See if any of our timers were started, if so add them to TimersToPrint and
336  // reset them.
337  for (Timer *T = FirstTimer; T; T = T->Next) {
338  if (!T->hasTriggered()) continue;
339  TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
340 
341  // Clear out the time.
342  T->clear();
343  }
344 }
345 
347  sys::SmartScopedLock<true> L(*TimerLock);
348 
349  prepareToPrintList();
350 
351  // If any timers were started, print the group.
352  if (!TimersToPrint.empty())
353  PrintQueuedTimers(OS);
354 }
355 
357  sys::SmartScopedLock<true> L(*TimerLock);
358 
359  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
360  TG->print(OS);
361 }
362 
363 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
364  const char *suffix, double Value) {
365  assert(!yaml::needsQuotes(Name) && "TimerGroup name needs no quotes");
366  assert(!yaml::needsQuotes(R.Name) && "Timer name needs no quotes");
367  OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value;
368 }
369 
370 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
371  prepareToPrintList();
372  for (const PrintRecord &R : TimersToPrint) {
373  OS << delim;
374  delim = ",\n";
375 
376  const TimeRecord &T = R.Time;
377  printJSONValue(OS, R, ".wall", T.getWallTime());
378  OS << delim;
379  printJSONValue(OS, R, ".user", T.getUserTime());
380  OS << delim;
381  printJSONValue(OS, R, ".sys", T.getSystemTime());
382  }
383  TimersToPrint.clear();
384  return delim;
385 }
386 
387 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
388  sys::SmartScopedLock<true> L(*TimerLock);
389  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
390  delim = TG->printJSONValues(OS, delim);
391  return delim;
392 }
393 
395  (void)*NamedGroupedTimers;
396 }
const_iterator end(StringRef path)
Get end iterator over path.
Definition: Path.cpp:243
F_Append - When opening a file, if it already exists append to the existing file instead of returning...
Definition: FileSystem.h:704
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:112
const_iterator begin(StringRef path, Style style=Style::native)
Get begin iterator over path.
Definition: Path.cpp:234
void init(StringRef Name, StringRef Description)
Definition: Timer.cpp:89
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:138
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 needsQuotes(StringRef S)
Definition: YAMLTraits.h:498
The TimeRegion class is used as a helper class to call the startTimer() and stopTimer() methods of th...
Definition: Timer.h:140
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
auto count(R &&Range, const E &Element) -> typename std::iterator_traits< decltype(std::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:880
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:157
static void printVal(double Val, double Total, raw_ostream &OS)
Definition: Timer.cpp:150
std::unique_ptr< raw_fd_ostream > CreateInfoOutputFile()
Return a file stream to print our output on.
Definition: Timer.cpp:53
const char * Name
static TimerGroup * TimerGroupList
This is the global list of TimerGroups, maintained by the TimerGroup ctor/dtor and is protected by th...
Definition: Timer.cpp:223
initializer< Ty > init(const Ty &Val)
Definition: CommandLine.h:404
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
void clear()
Clear the timer state.
Definition: Timer.cpp:145
static ManagedStatic< std::string > LibSupportInfoOutputFilename
Definition: Timer.cpp:34
static ManagedStatic< Name2PairMap > NamedGroupedTimers
Definition: Timer.cpp:208
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:346
ssize_t getMemUsed() const
Definition: Timer.h:44
iterator_range< T > make_range(T x, T y)
Convenience function for iterating over sub-ranges.
#define E
Definition: LargeTest.cpp:27
double getProcessTime() const
Definition: Timer.h:40
static TimerGroup * getDefaultTimerGroup()
Definition: Timer.cpp:83
double getSystemTime() const
Definition: Timer.h:42
bool isInitialized() const
Definition: Timer.h:110
void startTimer()
Start the timer running.
Definition: Timer.cpp:132
static bool Enabled
Definition: Statistic.cpp:49
StringMap - This is an unconventional map that is specialized for handling keys that are "strings"...
Definition: StringMap.h:224
static std::string & getLibSupportInfoOutputFilename()
Definition: Timer.cpp:35
The file should be opened in text mode on platforms that make this distinction.
Definition: FileSystem.h:708
iterator begin() const
Definition: StringRef.h:106
static ManagedStatic< TimerGroup, CreateDefaultTimerGroup > DefaultTimerGroup
Definition: Timer.cpp:82
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:387
Provides a library for accessing information about this process and other processes on the operating ...
iterator begin()
Definition: StringMap.h:319
#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:210
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
static void ConstructTimerLists()
Ensure global timer group lists are initialized.
Definition: Timer.cpp:394
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:356
This class implements an extremely fast bulk output stream that can only output to a stream...
Definition: raw_ostream.h:44
static size_t getMemUsage()
Definition: Timer.cpp:107
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
void sort(Policy policy, RandomAccessIterator Start, RandomAccessIterator End, const Comparator &Comp=Comparator())
Definition: Parallel.h:201
iterator end() const
Definition: StringRef.h:108
LocationClass< Ty > location(Ty &L)
Definition: CommandLine.h:420
iterator end()
Definition: StringMap.h:322
static ManagedStatic< sys::SmartMutex< true > > TimerLock
Definition: Timer.cpp:39
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:34