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