Timer.cpp revision 0ea86bc411748f10b913f42ef3a71b46ace7ceb2 
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/Debug.h"
15#include "llvm/Support/Timer.h"
16#include "llvm/Support/CommandLine.h"
17#include "llvm/Support/ManagedStatic.h"
18#include "llvm/Support/raw_ostream.h"
19#include "llvm/Support/Format.h"
20#include "llvm/System/Process.h"
21#include <algorithm>
22#include <functional>
23#include <map>
24using namespace llvm;
25
26// GetLibSupportInfoOutputFile - Return a file stream to print our output on.
27namespace llvm { extern raw_ostream *GetLibSupportInfoOutputFile(); }
28
29// getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
30// of constructor/destructor ordering being unspecified by C++.  Basically the
31// problem is that a Statistic object gets destroyed, which ends up calling
32// 'GetLibSupportInfoOutputFile()' (below), which calls this function.
33// LibSupportInfoOutputFilename used to be a global variable, but sometimes it
34// would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
35// this by creating the string the first time it is needed and never destroying
36// it.
37static ManagedStatic<std::string> LibSupportInfoOutputFilename;
38static std::string &getLibSupportInfoOutputFilename() {
39  return *LibSupportInfoOutputFilename;
40}
41
42static ManagedStatic<sys::SmartMutex<true> > TimerLock;
43
44namespace {
45  static cl::opt<bool>
46  TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
47                                      "tracking (this may be slow)"),
48             cl::Hidden);
49
50  static cl::opt<std::string, true>
51  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
52                     cl::desc("File to append -stats and -timer output to"),
53                   cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
54}
55
56static TimerGroup *DefaultTimerGroup = 0;
57static TimerGroup *getDefaultTimerGroup() {
58  TimerGroup *tmp = DefaultTimerGroup;
59  sys::MemoryFence();
60  if (tmp) return tmp;
61
62  llvm_acquire_global_lock();
63  tmp = DefaultTimerGroup;
64  if (!tmp) {
65    tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
66    sys::MemoryFence();
67    DefaultTimerGroup = tmp;
68  }
69  llvm_release_global_lock();
70
71  return tmp;
72}
73
74//===----------------------------------------------------------------------===//
75// Timer Implementation
76//===----------------------------------------------------------------------===//
77
78Timer::Timer(const std::string &N)
79  : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
80    Started(false), TG(getDefaultTimerGroup()) {
81  TG->addTimer();
82}
83
84Timer::Timer(const std::string &N, TimerGroup &tg)
85  : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
86    Started(false), TG(&tg) {
87  TG->addTimer();
88}
89
90Timer::Timer(const Timer &T) {
91  TG = T.TG;
92  if (TG) TG->addTimer();
93  operator=(T);
94}
95
96// Copy ctor, initialize with no TG member.
97Timer::Timer(bool, const Timer &T) {
98  TG = T.TG;     // Avoid assertion in operator=
99  operator=(T);  // Copy contents
100  TG = 0;
101}
102
103Timer::~Timer() {
104  if (!TG) return;
105
106  if (Started) {
107    Started = false;
108    TG->addTimerToPrint(*this);
109  }
110  TG->removeTimer();
111}
112
113static inline size_t getMemUsage() {
114  if (TrackSpace)
115    return sys::Process::GetMallocUsage();
116  return 0;
117}
118
119struct TimeRecord {
120  double Elapsed, UserTime, SystemTime;
121  ssize_t MemUsed;
122};
123
124static TimeRecord getTimeRecord(bool Start) {
125  TimeRecord Result;
126
127  sys::TimeValue now(0,0);
128  sys::TimeValue user(0,0);
129  sys::TimeValue sys(0,0);
130
131  ssize_t MemUsed = 0;
132  if (Start) {
133    MemUsed = getMemUsage();
134    sys::Process::GetTimeUsage(now, user, sys);
135  } else {
136    sys::Process::GetTimeUsage(now, user, sys);
137    MemUsed = getMemUsage();
138  }
139
140  Result.Elapsed    =  now.seconds()  + now.microseconds() / 1000000.0;
141  Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
142  Result.SystemTime =  sys.seconds()  + sys.microseconds() / 1000000.0;
143  Result.MemUsed = MemUsed;
144  return Result;
145}
146
147static ManagedStatic<std::vector<Timer*> > ActiveTimers;
148
149void Timer::startTimer() {
150  Started = true;
151  ActiveTimers->push_back(this);
152  TimeRecord TR = getTimeRecord(true);
153  Elapsed    -= TR.Elapsed;
154  UserTime   -= TR.UserTime;
155  SystemTime -= TR.SystemTime;
156  MemUsed    -= TR.MemUsed;
157  PeakMemBase = TR.MemUsed;
158}
159
160void Timer::stopTimer() {
161  TimeRecord TR = getTimeRecord(false);
162  Elapsed    += TR.Elapsed;
163  UserTime   += TR.UserTime;
164  SystemTime += TR.SystemTime;
165  MemUsed    += TR.MemUsed;
166
167  if (ActiveTimers->back() == this) {
168    ActiveTimers->pop_back();
169  } else {
170    std::vector<Timer*>::iterator I =
171      std::find(ActiveTimers->begin(), ActiveTimers->end(), this);
172    assert(I != ActiveTimers->end() && "stop but no startTimer?");
173    ActiveTimers->erase(I);
174  }
175}
176
177void Timer::sum(const Timer &T) {
178  Elapsed    += T.Elapsed;
179  UserTime   += T.UserTime;
180  SystemTime += T.SystemTime;
181  MemUsed    += T.MemUsed;
182  PeakMem    += T.PeakMem;
183}
184
185const Timer &Timer::operator=(const Timer &T) {
186  Elapsed = T.Elapsed;
187  UserTime = T.UserTime;
188  SystemTime = T.SystemTime;
189  MemUsed = T.MemUsed;
190  PeakMem = T.PeakMem;
191  PeakMemBase = T.PeakMemBase;
192  Name = T.Name;
193  Started = T.Started;
194  assert(TG == T.TG && "Can only assign timers in the same TimerGroup!");
195  return *this;
196}
197
198
199/// addPeakMemoryMeasurement - This method should be called whenever memory
200/// usage needs to be checked.  It adds a peak memory measurement to the
201/// currently active timers, which will be printed when the timer group prints
202///
203void Timer::addPeakMemoryMeasurement() {
204  size_t MemUsed = getMemUsage();
205  for (std::vector<Timer*>::iterator I = ActiveTimers->begin(),
206         E = ActiveTimers->end(); I != E; ++I)
207    (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase);
208}
209
210
211static void printVal(double Val, double Total, raw_ostream &OS) {
212  if (Total < 1e-7)   // Avoid dividing by zero.
213    OS << "        -----     ";
214  else {
215    OS << "  " << format("%7.4f", Val) << " (";
216    OS << format("%5.1f", Val*100/Total) << "%)";
217  }
218}
219
220void Timer::print(const Timer &Total, raw_ostream &OS) {
221  if (Total.UserTime)
222    printVal(UserTime, Total.UserTime, OS);
223  if (Total.SystemTime)
224    printVal(SystemTime, Total.SystemTime, OS);
225  if (Total.getProcessTime())
226    printVal(getProcessTime(), Total.getProcessTime(), OS);
227  printVal(Elapsed, Total.Elapsed, OS);
228
229  OS << "  ";
230
231  if (Total.MemUsed)
232    OS << format("%9lld", (long long)MemUsed) << "  ";
233
234  if (Total.PeakMem) {
235    if (PeakMem)
236      OS << format("%9lld", (long long)PeakMem) << "  ";
237    else
238      OS << "           ";
239  }
240  OS << Name << "\n";
241
242  Started = false;  // Once printed, don't print again
243}
244
245
246//===----------------------------------------------------------------------===//
247//   NamedRegionTimer Implementation
248//===----------------------------------------------------------------------===//
249
250typedef std::map<std::string, Timer> Name2Timer;
251typedef std::map<std::string, std::pair<TimerGroup, Name2Timer> > Name2Pair;
252
253static ManagedStatic<Name2Timer> NamedTimers;
254static ManagedStatic<Name2Pair> NamedGroupedTimers;
255
256static Timer &getNamedRegionTimer(const std::string &Name) {
257  sys::SmartScopedLock<true> L(*TimerLock);
258  Name2Timer::iterator I = NamedTimers->find(Name);
259  if (I != NamedTimers->end())
260    return I->second;
261
262  return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second;
263}
264
265static Timer &getNamedRegionTimer(const std::string &Name,
266                                  const std::string &GroupName) {
267  sys::SmartScopedLock<true> L(*TimerLock);
268
269  Name2Pair::iterator I = NamedGroupedTimers->find(GroupName);
270  if (I == NamedGroupedTimers->end()) {
271    TimerGroup TG(GroupName);
272    std::pair<TimerGroup, Name2Timer> Pair(TG, Name2Timer());
273    I = NamedGroupedTimers->insert(I, std::make_pair(GroupName, Pair));
274  }
275
276  Name2Timer::iterator J = I->second.second.find(Name);
277  if (J == I->second.second.end())
278    J = I->second.second.insert(J,
279                                std::make_pair(Name,
280                                               Timer(Name,
281                                                     I->second.first)));
282
283  return J->second;
284}
285
286NamedRegionTimer::NamedRegionTimer(const std::string &Name)
287  : TimeRegion(getNamedRegionTimer(Name)) {}
288
289NamedRegionTimer::NamedRegionTimer(const std::string &Name,
290                                   const std::string &GroupName)
291  : TimeRegion(getNamedRegionTimer(Name, GroupName)) {}
292
293//===----------------------------------------------------------------------===//
294//   TimerGroup Implementation
295//===----------------------------------------------------------------------===//
296
297// GetLibSupportInfoOutputFile - Return a file stream to print our output on.
298raw_ostream *llvm::GetLibSupportInfoOutputFile() {
299  std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename();
300  if (LibSupportInfoOutputFilename.empty())
301    return &errs();
302  if (LibSupportInfoOutputFilename == "-")
303    return &outs();
304
305  std::string Error;
306  raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(),
307                                           Error, raw_fd_ostream::F_Append);
308  if (Error.empty())
309    return Result;
310
311  errs() << "Error opening info-output-file '"
312         << LibSupportInfoOutputFilename << " for appending!\n";
313  delete Result;
314  return &errs();
315}
316
317
318void TimerGroup::removeTimer() {
319  sys::SmartScopedLock<true> L(*TimerLock);
320  if (--NumTimers != 0 || TimersToPrint.empty())
321    return; // Don't print timing report.
322
323  // Sort the timers in descending order by amount of time taken.
324  std::sort(TimersToPrint.begin(), TimersToPrint.end(),
325            std::greater<Timer>());
326
327  // Figure out how many spaces to indent TimerGroup name.
328  unsigned Padding = (80-Name.length())/2;
329  if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
330
331  raw_ostream *OutStream = GetLibSupportInfoOutputFile();
332
333  ++NumTimers;
334  {  // Scope to contain Total timer: don't allow total timer to drop us to
335     // zero timers.
336    Timer Total("TOTAL");
337
338    for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
339      Total.sum(TimersToPrint[i]);
340
341    // Print out timing header.
342    *OutStream << "===" << std::string(73, '-') << "===\n"
343               << std::string(Padding, ' ') << Name << "\n"
344               << "===" << std::string(73, '-')
345               << "===\n";
346
347    // If this is not an collection of ungrouped times, print the total time.
348    // Ungrouped timers don't really make sense to add up.  We still print the
349    // TOTAL line to make the percentages make sense.
350    if (this != DefaultTimerGroup) {
351      *OutStream << "  Total Execution Time: ";
352
353      *OutStream << format("%5.4f", Total.getProcessTime()) << " seconds (";
354      *OutStream << format("%5.4f", Total.getWallTime()) << " wall clock)\n";
355    }
356    *OutStream << "\n";
357
358    if (Total.UserTime)
359      *OutStream << "   ---User Time---";
360    if (Total.SystemTime)
361      *OutStream << "   --System Time--";
362    if (Total.getProcessTime())
363      *OutStream << "   --User+System--";
364    *OutStream << "   ---Wall Time---";
365    if (Total.getMemUsed())
366      *OutStream << "  ---Mem---";
367    if (Total.getPeakMem())
368      *OutStream << "  -PeakMem-";
369    *OutStream << "  --- Name ---\n";
370
371    // Loop through all of the timing data, printing it out.
372    for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
373      TimersToPrint[i].print(Total, *OutStream);
374
375    Total.print(Total, *OutStream);
376    *OutStream << '\n';
377    OutStream->flush();
378  }
379  --NumTimers;
380
381  TimersToPrint.clear();
382
383  if (OutStream != &errs() && OutStream != &outs())
384    delete OutStream;   // Close the file.
385}
386
387void TimerGroup::addTimer() {
388  sys::SmartScopedLock<true> L(*TimerLock);
389  ++NumTimers;
390}
391
392void TimerGroup::addTimerToPrint(const Timer &T) {
393  sys::SmartScopedLock<true> L(*TimerLock);
394  TimersToPrint.push_back(Timer(true, T));
395}
396
397