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