Timer.cpp revision 49a2bb23d1391c8be45985518d4c5e99ff11b864 
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/Debug.h"
17#include "llvm/Support/ManagedStatic.h"
18#include "llvm/Support/raw_ostream.h"
19#include "llvm/Support/Format.h"
20#include "llvm/System/Mutex.h"
21#include "llvm/System/Process.h"
22#include "llvm/ADT/StringMap.h"
23using namespace llvm;
24
25// CreateInfoOutputFile - Return a file stream to print our output on.
26namespace llvm { extern raw_ostream *CreateInfoOutputFile(); }
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
41static ManagedStatic<sys::SmartMutex<true> > TimerLock;
42
43namespace {
44  static cl::opt<bool>
45  TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
46                                      "tracking (this may be slow)"),
47             cl::Hidden);
48
49  static cl::opt<std::string, true>
50  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
51                     cl::desc("File to append -stats and -timer output to"),
52                   cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
53}
54
55// CreateInfoOutputFile - Return a file stream to print our output on.
56raw_ostream *llvm::CreateInfoOutputFile() {
57  std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename();
58  if (LibSupportInfoOutputFilename.empty())
59    return new raw_fd_ostream(2, false); // stderr.
60  if (LibSupportInfoOutputFilename == "-")
61    return new raw_fd_ostream(1, false); // stdout.
62
63  std::string Error;
64  raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(),
65                                           Error, raw_fd_ostream::F_Append);
66  if (Error.empty())
67    return Result;
68
69  errs() << "Error opening info-output-file '"
70    << LibSupportInfoOutputFilename << " for appending!\n";
71  delete Result;
72  return new raw_fd_ostream(2, false); // stderr.
73}
74
75
76static TimerGroup *DefaultTimerGroup = 0;
77static TimerGroup *getDefaultTimerGroup() {
78  TimerGroup *tmp = DefaultTimerGroup;
79  sys::MemoryFence();
80  if (tmp) return tmp;
81
82  llvm_acquire_global_lock();
83  tmp = DefaultTimerGroup;
84  if (!tmp) {
85    tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
86    sys::MemoryFence();
87    DefaultTimerGroup = tmp;
88  }
89  llvm_release_global_lock();
90
91  return tmp;
92}
93
94//===----------------------------------------------------------------------===//
95// Timer Implementation
96//===----------------------------------------------------------------------===//
97
98void Timer::init(const std::string &N) {
99  assert(TG == 0 && "Timer already initialized");
100  Name = N;
101  Started = false;
102  TG = getDefaultTimerGroup();
103  TG->addTimer(*this);
104}
105
106void Timer::init(const std::string &N, TimerGroup &tg) {
107  assert(TG == 0 && "Timer already initialized");
108  Name = N;
109  Started = false;
110  TG = &tg;
111  TG->addTimer(*this);
112}
113
114Timer::~Timer() {
115  if (!TG) return;  // Never initialized.
116  TG->removeTimer(*this);
117}
118
119static inline size_t getMemUsage() {
120  if (TrackSpace)
121    return sys::Process::GetMallocUsage();
122  return 0;
123}
124
125TimeRecord TimeRecord::getCurrentTime(bool Start) {
126  TimeRecord Result;
127
128  sys::TimeValue now(0,0);
129  sys::TimeValue user(0,0);
130  sys::TimeValue sys(0,0);
131
132  ssize_t MemUsed = 0;
133  if (Start) {
134    MemUsed = getMemUsage();
135    sys::Process::GetTimeUsage(now, user, sys);
136  } else {
137    sys::Process::GetTimeUsage(now, user, sys);
138    MemUsed = getMemUsage();
139  }
140
141  Result.WallTime   =  now.seconds() +  now.microseconds() / 1000000.0;
142  Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
143  Result.SystemTime =  sys.seconds() +  sys.microseconds() / 1000000.0;
144  Result.MemUsed = MemUsed;
145  return Result;
146}
147
148static ManagedStatic<std::vector<Timer*> > ActiveTimers;
149
150void Timer::startTimer() {
151  Started = true;
152  ActiveTimers->push_back(this);
153  Time -= TimeRecord::getCurrentTime(true);
154}
155
156void Timer::stopTimer() {
157  Time += TimeRecord::getCurrentTime(false);
158
159  if (ActiveTimers->back() == this) {
160    ActiveTimers->pop_back();
161  } else {
162    std::vector<Timer*>::iterator I =
163      std::find(ActiveTimers->begin(), ActiveTimers->end(), this);
164    assert(I != ActiveTimers->end() && "stop but no startTimer?");
165    ActiveTimers->erase(I);
166  }
167}
168
169static void printVal(double Val, double Total, raw_ostream &OS) {
170  if (Total < 1e-7)   // Avoid dividing by zero.
171    OS << "        -----     ";
172  else {
173    OS << "  " << format("%7.4f", Val) << " (";
174    OS << format("%5.1f", Val*100/Total) << "%)";
175  }
176}
177
178void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
179  if (Total.getUserTime())
180    printVal(getUserTime(), Total.getUserTime(), OS);
181  if (Total.getSystemTime())
182    printVal(getSystemTime(), Total.getSystemTime(), OS);
183  if (Total.getProcessTime())
184    printVal(getProcessTime(), Total.getProcessTime(), OS);
185  printVal(getWallTime(), Total.getWallTime(), OS);
186
187  OS << "  ";
188
189  if (Total.getMemUsed())
190    OS << format("%9lld", (long long)getMemUsed()) << "  ";
191}
192
193
194//===----------------------------------------------------------------------===//
195//   NamedRegionTimer Implementation
196//===----------------------------------------------------------------------===//
197
198typedef StringMap<Timer> Name2TimerMap;
199typedef StringMap<std::pair<TimerGroup, Name2TimerMap> > Name2PairMap;
200
201static ManagedStatic<Name2TimerMap> NamedTimers;
202static ManagedStatic<Name2PairMap> NamedGroupedTimers;
203
204static Timer &getNamedRegionTimer(const std::string &Name) {
205  sys::SmartScopedLock<true> L(*TimerLock);
206
207  Timer &T = (*NamedTimers)[Name];
208  if (!T.isInitialized())
209    T.init(Name);
210  return T;
211}
212
213static Timer &getNamedRegionTimer(const std::string &Name,
214                                  const std::string &GroupName) {
215  sys::SmartScopedLock<true> L(*TimerLock);
216
217  std::pair<TimerGroup, Name2TimerMap> &GroupEntry =
218    (*NamedGroupedTimers)[GroupName];
219
220  if (GroupEntry.second.empty())
221    GroupEntry.first.setName(GroupName);
222
223  Timer &T = GroupEntry.second[Name];
224  if (!T.isInitialized())
225    T.init(Name);
226  return T;
227}
228
229NamedRegionTimer::NamedRegionTimer(const std::string &Name)
230  : TimeRegion(getNamedRegionTimer(Name)) {}
231
232NamedRegionTimer::NamedRegionTimer(const std::string &Name,
233                                   const std::string &GroupName)
234  : TimeRegion(getNamedRegionTimer(Name, GroupName)) {}
235
236//===----------------------------------------------------------------------===//
237//   TimerGroup Implementation
238//===----------------------------------------------------------------------===//
239
240TimerGroup::~TimerGroup() {
241  // If the timer group is destroyed before the timers it owns, accumulate and
242  // print the timing data.
243  while (FirstTimer != 0)
244    removeTimer(*FirstTimer);
245}
246
247
248void TimerGroup::removeTimer(Timer &T) {
249  sys::SmartScopedLock<true> L(*TimerLock);
250
251  // If the timer was started, move its data to TimersToPrint.
252  if (T.Started)
253    TimersToPrint.push_back(std::make_pair(T.Time, T.Name));
254
255  T.TG = 0;
256
257  // Unlink the timer from our list.
258  *T.Prev = T.Next;
259  if (T.Next)
260    T.Next->Prev = T.Prev;
261
262  // Print the report when all timers in this group are destroyed if some of
263  // them were started.
264  if (FirstTimer != 0 || TimersToPrint.empty())
265    return;
266
267  raw_ostream *OutStream = CreateInfoOutputFile();
268  PrintQueuedTimers(*OutStream);
269  delete OutStream;   // Close the file.
270}
271
272void TimerGroup::addTimer(Timer &T) {
273  sys::SmartScopedLock<true> L(*TimerLock);
274
275  // Add the timer to our list.
276  if (FirstTimer)
277    FirstTimer->Prev = &T.Next;
278  T.Next = FirstTimer;
279  T.Prev = &FirstTimer;
280  FirstTimer = &T;
281}
282
283void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
284  // Sort the timers in descending order by amount of time taken.
285  std::sort(TimersToPrint.begin(), TimersToPrint.end());
286
287  TimeRecord Total;
288  for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
289    Total += TimersToPrint[i].first;
290
291  // Print out timing header.
292  OS << "===" << std::string(73, '-') << "===\n";
293  // Figure out how many spaces to indent TimerGroup name.
294  unsigned Padding = (80-Name.length())/2;
295  if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
296  OS.indent(Padding) << Name << '\n';
297  OS << "===" << std::string(73, '-') << "===\n";
298
299  // If this is not an collection of ungrouped times, print the total time.
300  // Ungrouped timers don't really make sense to add up.  We still print the
301  // TOTAL line to make the percentages make sense.
302  if (this != DefaultTimerGroup) {
303    OS << "  Total Execution Time: ";
304    OS << format("%5.4f", Total.getProcessTime()) << " seconds (";
305    OS << format("%5.4f", Total.getWallTime()) << " wall clock)\n";
306  }
307  OS << '\n';
308
309  if (Total.getUserTime())
310    OS << "   ---User Time---";
311  if (Total.getSystemTime())
312    OS << "   --System Time--";
313  if (Total.getProcessTime())
314    OS << "   --User+System--";
315  OS << "   ---Wall Time---";
316  if (Total.getMemUsed())
317    OS << "  ---Mem---";
318  OS << "  --- Name ---\n";
319
320  // Loop through all of the timing data, printing it out.
321  for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
322    const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
323    Entry.first.print(Total, OS);
324    OS << Entry.second << '\n';
325  }
326
327  Total.print(Total, OS);
328  OS << "Total\n\n";
329  OS.flush();
330
331  TimersToPrint.clear();
332}
333
334