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// Interval Timing implementation.
11//
12//===----------------------------------------------------------------------===//
13
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"
24using namespace llvm;
25
26// getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
27// of constructor/destructor ordering being unspecified by C++.  Basically the
28// problem is that a Statistic object gets destroyed, which ends up calling
29// 'GetLibSupportInfoOutputFile()' (below), which calls this function.
30// LibSupportInfoOutputFilename used to be a global variable, but sometimes it
31// would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
32// this by creating the string the first time it is needed and never destroying
33// it.
34static ManagedStatic<std::string> LibSupportInfoOutputFilename;
35static std::string &getLibSupportInfoOutputFilename() {
36  return *LibSupportInfoOutputFilename;
37}
38
39static ManagedStatic<sys::SmartMutex<true> > TimerLock;
40
41namespace {
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
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()));
51}
52
53// Return a file stream to print our output on.
54std::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>(
67      OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
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
77static TimerGroup *DefaultTimerGroup = nullptr;
78static TimerGroup *getDefaultTimerGroup() {
79  TimerGroup *tmp = DefaultTimerGroup;
80  sys::MemoryFence();
81  if (tmp) return tmp;
82
83  sys::SmartScopedLock<true> Lock(*TimerLock);
84  tmp = DefaultTimerGroup;
85  if (!tmp) {
86    tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
87    sys::MemoryFence();
88    DefaultTimerGroup = tmp;
89  }
90
91  return tmp;
92}
93
94//===----------------------------------------------------------------------===//
95// Timer Implementation
96//===----------------------------------------------------------------------===//
97
98void Timer::init(StringRef N) {
99  init(N, *getDefaultTimerGroup());
100}
101
102void Timer::init(StringRef N, TimerGroup &tg) {
103  assert(!TG && "Timer already initialized");
104  Name.assign(N.begin(), N.end());
105  Running = Triggered = false;
106  TG = &tg;
107  TG->addTimer(*this);
108}
109
110Timer::~Timer() {
111  if (!TG) return;  // Never initialized, or already cleared.
112  TG->removeTimer(*this);
113}
114
115static inline size_t getMemUsage() {
116  if (!TrackSpace) return 0;
117  return sys::Process::GetMallocUsage();
118}
119
120TimeRecord TimeRecord::getCurrentTime(bool Start) {
121  TimeRecord Result;
122  sys::TimeValue now(0,0), user(0,0), sys(0,0);
123
124  if (Start) {
125    Result.MemUsed = getMemUsage();
126    sys::Process::GetTimeUsage(now, user, sys);
127  } else {
128    sys::Process::GetTimeUsage(now, user, sys);
129    Result.MemUsed = getMemUsage();
130  }
131
132  Result.WallTime   =  now.seconds() +  now.microseconds() / 1000000.0;
133  Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
134  Result.SystemTime =  sys.seconds() +  sys.microseconds() / 1000000.0;
135  return Result;
136}
137
138void Timer::startTimer() {
139  assert(!Running && "Cannot start a running timer");
140  Running = Triggered = true;
141  StartTime = TimeRecord::getCurrentTime(true);
142}
143
144void Timer::stopTimer() {
145  assert(Running && "Cannot stop a paused timer");
146  Running = false;
147  Time += TimeRecord::getCurrentTime(false);
148  Time -= StartTime;
149}
150
151void Timer::clear() {
152  Running = Triggered = false;
153  Time = StartTime = TimeRecord();
154}
155
156static void printVal(double Val, double Total, raw_ostream &OS) {
157  if (Total < 1e-7)   // Avoid dividing by zero.
158    OS << "        -----     ";
159  else
160    OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
161}
162
163void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
164  if (Total.getUserTime())
165    printVal(getUserTime(), Total.getUserTime(), OS);
166  if (Total.getSystemTime())
167    printVal(getSystemTime(), Total.getSystemTime(), OS);
168  if (Total.getProcessTime())
169    printVal(getProcessTime(), Total.getProcessTime(), OS);
170  printVal(getWallTime(), Total.getWallTime(), OS);
171
172  OS << "  ";
173
174  if (Total.getMemUsed())
175    OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
176}
177
178
179//===----------------------------------------------------------------------===//
180//   NamedRegionTimer Implementation
181//===----------------------------------------------------------------------===//
182
183namespace {
184
185typedef StringMap<Timer> Name2TimerMap;
186
187class Name2PairMap {
188  StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
189public:
190  ~Name2PairMap() {
191    for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
192         I = Map.begin(), E = Map.end(); I != E; ++I)
193      delete I->second.first;
194  }
195
196  Timer &get(StringRef Name, StringRef GroupName) {
197    sys::SmartScopedLock<true> L(*TimerLock);
198
199    std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
200
201    if (!GroupEntry.first)
202      GroupEntry.first = new TimerGroup(GroupName);
203
204    Timer &T = GroupEntry.second[Name];
205    if (!T.isInitialized())
206      T.init(Name, *GroupEntry.first);
207    return T;
208  }
209};
210
211}
212
213static ManagedStatic<Name2TimerMap> NamedTimers;
214static ManagedStatic<Name2PairMap> NamedGroupedTimers;
215
216static Timer &getNamedRegionTimer(StringRef Name) {
217  sys::SmartScopedLock<true> L(*TimerLock);
218
219  Timer &T = (*NamedTimers)[Name];
220  if (!T.isInitialized())
221    T.init(Name);
222  return T;
223}
224
225NamedRegionTimer::NamedRegionTimer(StringRef Name,
226                                   bool Enabled)
227  : TimeRegion(!Enabled ? nullptr : &getNamedRegionTimer(Name)) {}
228
229NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName,
230                                   bool Enabled)
231  : TimeRegion(!Enabled ? nullptr : &NamedGroupedTimers->get(Name, GroupName)){}
232
233//===----------------------------------------------------------------------===//
234//   TimerGroup Implementation
235//===----------------------------------------------------------------------===//
236
237/// TimerGroupList - This is the global list of TimerGroups, maintained by the
238/// TimerGroup ctor/dtor and is protected by the TimerLock lock.
239static TimerGroup *TimerGroupList = nullptr;
240
241TimerGroup::TimerGroup(StringRef name)
242  : Name(name.begin(), name.end()), FirstTimer(nullptr) {
243
244  // Add the group to TimerGroupList.
245  sys::SmartScopedLock<true> L(*TimerLock);
246  if (TimerGroupList)
247    TimerGroupList->Prev = &Next;
248  Next = TimerGroupList;
249  Prev = &TimerGroupList;
250  TimerGroupList = this;
251}
252
253TimerGroup::~TimerGroup() {
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
267void 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);
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
290void 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
301void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
302  // Sort the timers in descending order by amount of time taken.
303  std::sort(TimersToPrint.begin(), TimersToPrint.end());
304
305  TimeRecord Total;
306  for (auto &RecordNamePair : TimersToPrint)
307    Total += RecordNamePair.first;
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-Name.length())/2;
313  if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
314  OS.indent(Padding) << Name << '\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 != DefaultTimerGroup)
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 (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
338    const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
339    Entry.first.print(Total, OS);
340    OS << Entry.second << '\n';
341  }
342
343  Total.print(Total, OS);
344  OS << "Total\n\n";
345  OS.flush();
346
347  TimersToPrint.clear();
348}
349
350/// print - Print any started timers in this group and zero them.
351void TimerGroup::print(raw_ostream &OS) {
352  sys::SmartScopedLock<true> L(*TimerLock);
353
354  // See if any of our timers were started, if so add them to TimersToPrint and
355  // reset them.
356  for (Timer *T = FirstTimer; T; T = T->Next) {
357    if (!T->hasTriggered()) continue;
358    TimersToPrint.emplace_back(T->Time, T->Name);
359
360    // Clear out the time.
361    T->clear();
362  }
363
364  // If any timers were started, print the group.
365  if (!TimersToPrint.empty())
366    PrintQueuedTimers(OS);
367}
368
369/// printAll - This static method prints all timers and clears them all out.
370void TimerGroup::printAll(raw_ostream &OS) {
371  sys::SmartScopedLock<true> L(*TimerLock);
372
373  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
374    TG->print(OS);
375}
376