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