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