• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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/ADT/StringMap.h"
16 #include "llvm/Support/CommandLine.h"
17 #include "llvm/Support/Debug.h"
18 #include "llvm/Support/FileSystem.h"
19 #include "llvm/Support/Format.h"
20 #include "llvm/Support/ManagedStatic.h"
21 #include "llvm/Support/Mutex.h"
22 #include "llvm/Support/MutexGuard.h"
23 #include "llvm/Support/Process.h"
24 #include "llvm/Support/raw_ostream.h"
25 using namespace llvm;
26 
27 // CreateInfoOutputFile - Return a file stream to print our output on.
28 namespace llvm { extern raw_ostream *CreateInfoOutputFile(); }
29 
30 // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
31 // of constructor/destructor ordering being unspecified by C++.  Basically the
32 // problem is that a Statistic object gets destroyed, which ends up calling
33 // 'GetLibSupportInfoOutputFile()' (below), which calls this function.
34 // LibSupportInfoOutputFilename used to be a global variable, but sometimes it
35 // would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
36 // this by creating the string the first time it is needed and never destroying
37 // it.
38 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
getLibSupportInfoOutputFilename()39 static std::string &getLibSupportInfoOutputFilename() {
40   return *LibSupportInfoOutputFilename;
41 }
42 
43 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
44 
45 namespace {
46   static cl::opt<bool>
47   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
48                                       "tracking (this may be slow)"),
49              cl::Hidden);
50 
51   static cl::opt<std::string, true>
52   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
53                      cl::desc("File to append -stats and -timer output to"),
54                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
55 }
56 
57 // CreateInfoOutputFile - Return a file stream to print our output on.
CreateInfoOutputFile()58 raw_ostream *llvm::CreateInfoOutputFile() {
59   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
60   if (OutputFilename.empty())
61     return new raw_fd_ostream(2, false); // stderr.
62   if (OutputFilename == "-")
63     return new raw_fd_ostream(1, false); // stdout.
64 
65   // Append mode is used because the info output file is opened and closed
66   // each time -stats or -time-passes wants to print output to it. To
67   // compensate for this, the test-suite Makefiles have code to delete the
68   // info output file before running commands which write to it.
69   std::string Error;
70   raw_ostream *Result = new raw_fd_ostream(
71       OutputFilename.c_str(), Error, sys::fs::F_Append | sys::fs::F_Text);
72   if (Error.empty())
73     return Result;
74 
75   errs() << "Error opening info-output-file '"
76     << OutputFilename << " for appending!\n";
77   delete Result;
78   return new raw_fd_ostream(2, false); // stderr.
79 }
80 
81 
82 static TimerGroup *DefaultTimerGroup = nullptr;
getDefaultTimerGroup()83 static TimerGroup *getDefaultTimerGroup() {
84   TimerGroup *tmp = DefaultTimerGroup;
85   sys::MemoryFence();
86   if (tmp) return tmp;
87 
88   sys::SmartScopedLock<true> Lock(*TimerLock);
89   tmp = DefaultTimerGroup;
90   if (!tmp) {
91     tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
92     sys::MemoryFence();
93     DefaultTimerGroup = tmp;
94   }
95 
96   return tmp;
97 }
98 
99 //===----------------------------------------------------------------------===//
100 // Timer Implementation
101 //===----------------------------------------------------------------------===//
102 
init(StringRef N)103 void Timer::init(StringRef N) {
104   assert(!TG && "Timer already initialized");
105   Name.assign(N.begin(), N.end());
106   Started = false;
107   TG = getDefaultTimerGroup();
108   TG->addTimer(*this);
109 }
110 
init(StringRef N,TimerGroup & tg)111 void Timer::init(StringRef N, TimerGroup &tg) {
112   assert(!TG && "Timer already initialized");
113   Name.assign(N.begin(), N.end());
114   Started = false;
115   TG = &tg;
116   TG->addTimer(*this);
117 }
118 
~Timer()119 Timer::~Timer() {
120   if (!TG) return;  // Never initialized, or already cleared.
121   TG->removeTimer(*this);
122 }
123 
getMemUsage()124 static inline size_t getMemUsage() {
125   if (!TrackSpace) return 0;
126   return sys::Process::GetMallocUsage();
127 }
128 
getCurrentTime(bool Start)129 TimeRecord TimeRecord::getCurrentTime(bool Start) {
130   TimeRecord Result;
131   sys::TimeValue now(0,0), user(0,0), sys(0,0);
132 
133   if (Start) {
134     Result.MemUsed = getMemUsage();
135     sys::Process::GetTimeUsage(now, user, sys);
136   } else {
137     sys::Process::GetTimeUsage(now, user, sys);
138     Result.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   return Result;
145 }
146 
147 static ManagedStatic<std::vector<Timer*> > ActiveTimers;
148 
startTimer()149 void Timer::startTimer() {
150   Started = true;
151   ActiveTimers->push_back(this);
152   Time -= TimeRecord::getCurrentTime(true);
153 }
154 
stopTimer()155 void Timer::stopTimer() {
156   Time += TimeRecord::getCurrentTime(false);
157 
158   if (ActiveTimers->back() == this) {
159     ActiveTimers->pop_back();
160   } else {
161     std::vector<Timer*>::iterator I =
162       std::find(ActiveTimers->begin(), ActiveTimers->end(), this);
163     assert(I != ActiveTimers->end() && "stop but no startTimer?");
164     ActiveTimers->erase(I);
165   }
166 }
167 
printVal(double Val,double Total,raw_ostream & OS)168 static void printVal(double Val, double Total, raw_ostream &OS) {
169   if (Total < 1e-7)   // Avoid dividing by zero.
170     OS << "        -----     ";
171   else
172     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
173 }
174 
print(const TimeRecord & Total,raw_ostream & OS) const175 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
176   if (Total.getUserTime())
177     printVal(getUserTime(), Total.getUserTime(), OS);
178   if (Total.getSystemTime())
179     printVal(getSystemTime(), Total.getSystemTime(), OS);
180   if (Total.getProcessTime())
181     printVal(getProcessTime(), Total.getProcessTime(), OS);
182   printVal(getWallTime(), Total.getWallTime(), OS);
183 
184   OS << "  ";
185 
186   if (Total.getMemUsed())
187     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
188 }
189 
190 
191 //===----------------------------------------------------------------------===//
192 //   NamedRegionTimer Implementation
193 //===----------------------------------------------------------------------===//
194 
195 namespace {
196 
197 typedef StringMap<Timer> Name2TimerMap;
198 
199 class Name2PairMap {
200   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
201 public:
~Name2PairMap()202   ~Name2PairMap() {
203     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
204          I = Map.begin(), E = Map.end(); I != E; ++I)
205       delete I->second.first;
206   }
207 
get(StringRef Name,StringRef GroupName)208   Timer &get(StringRef Name, StringRef GroupName) {
209     sys::SmartScopedLock<true> L(*TimerLock);
210 
211     std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
212 
213     if (!GroupEntry.first)
214       GroupEntry.first = new TimerGroup(GroupName);
215 
216     Timer &T = GroupEntry.second[Name];
217     if (!T.isInitialized())
218       T.init(Name, *GroupEntry.first);
219     return T;
220   }
221 };
222 
223 }
224 
225 static ManagedStatic<Name2TimerMap> NamedTimers;
226 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
227 
getNamedRegionTimer(StringRef Name)228 static Timer &getNamedRegionTimer(StringRef Name) {
229   sys::SmartScopedLock<true> L(*TimerLock);
230 
231   Timer &T = (*NamedTimers)[Name];
232   if (!T.isInitialized())
233     T.init(Name);
234   return T;
235 }
236 
NamedRegionTimer(StringRef Name,bool Enabled)237 NamedRegionTimer::NamedRegionTimer(StringRef Name,
238                                    bool Enabled)
239   : TimeRegion(!Enabled ? nullptr : &getNamedRegionTimer(Name)) {}
240 
NamedRegionTimer(StringRef Name,StringRef GroupName,bool Enabled)241 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName,
242                                    bool Enabled)
243   : TimeRegion(!Enabled ? nullptr : &NamedGroupedTimers->get(Name, GroupName)){}
244 
245 //===----------------------------------------------------------------------===//
246 //   TimerGroup Implementation
247 //===----------------------------------------------------------------------===//
248 
249 /// TimerGroupList - This is the global list of TimerGroups, maintained by the
250 /// TimerGroup ctor/dtor and is protected by the TimerLock lock.
251 static TimerGroup *TimerGroupList = nullptr;
252 
TimerGroup(StringRef name)253 TimerGroup::TimerGroup(StringRef name)
254   : Name(name.begin(), name.end()), FirstTimer(nullptr) {
255 
256   // Add the group to TimerGroupList.
257   sys::SmartScopedLock<true> L(*TimerLock);
258   if (TimerGroupList)
259     TimerGroupList->Prev = &Next;
260   Next = TimerGroupList;
261   Prev = &TimerGroupList;
262   TimerGroupList = this;
263 }
264 
~TimerGroup()265 TimerGroup::~TimerGroup() {
266   // If the timer group is destroyed before the timers it owns, accumulate and
267   // print the timing data.
268   while (FirstTimer)
269     removeTimer(*FirstTimer);
270 
271   // Remove the group from the TimerGroupList.
272   sys::SmartScopedLock<true> L(*TimerLock);
273   *Prev = Next;
274   if (Next)
275     Next->Prev = Prev;
276 }
277 
278 
removeTimer(Timer & T)279 void TimerGroup::removeTimer(Timer &T) {
280   sys::SmartScopedLock<true> L(*TimerLock);
281 
282   // If the timer was started, move its data to TimersToPrint.
283   if (T.Started)
284     TimersToPrint.push_back(std::make_pair(T.Time, T.Name));
285 
286   T.TG = nullptr;
287 
288   // Unlink the timer from our list.
289   *T.Prev = T.Next;
290   if (T.Next)
291     T.Next->Prev = T.Prev;
292 
293   // Print the report when all timers in this group are destroyed if some of
294   // them were started.
295   if (FirstTimer || TimersToPrint.empty())
296     return;
297 
298   raw_ostream *OutStream = CreateInfoOutputFile();
299   PrintQueuedTimers(*OutStream);
300   delete OutStream;   // Close the file.
301 }
302 
addTimer(Timer & T)303 void TimerGroup::addTimer(Timer &T) {
304   sys::SmartScopedLock<true> L(*TimerLock);
305 
306   // Add the timer to our list.
307   if (FirstTimer)
308     FirstTimer->Prev = &T.Next;
309   T.Next = FirstTimer;
310   T.Prev = &FirstTimer;
311   FirstTimer = &T;
312 }
313 
PrintQueuedTimers(raw_ostream & OS)314 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
315   // Sort the timers in descending order by amount of time taken.
316   std::sort(TimersToPrint.begin(), TimersToPrint.end());
317 
318   TimeRecord Total;
319   for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
320     Total += TimersToPrint[i].first;
321 
322   // Print out timing header.
323   OS << "===" << std::string(73, '-') << "===\n";
324   // Figure out how many spaces to indent TimerGroup name.
325   unsigned Padding = (80-Name.length())/2;
326   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
327   OS.indent(Padding) << Name << '\n';
328   OS << "===" << std::string(73, '-') << "===\n";
329 
330   // If this is not an collection of ungrouped times, print the total time.
331   // Ungrouped timers don't really make sense to add up.  We still print the
332   // TOTAL line to make the percentages make sense.
333   if (this != DefaultTimerGroup)
334     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
335                  Total.getProcessTime(), Total.getWallTime());
336   OS << '\n';
337 
338   if (Total.getUserTime())
339     OS << "   ---User Time---";
340   if (Total.getSystemTime())
341     OS << "   --System Time--";
342   if (Total.getProcessTime())
343     OS << "   --User+System--";
344   OS << "   ---Wall Time---";
345   if (Total.getMemUsed())
346     OS << "  ---Mem---";
347   OS << "  --- Name ---\n";
348 
349   // Loop through all of the timing data, printing it out.
350   for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
351     const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
352     Entry.first.print(Total, OS);
353     OS << Entry.second << '\n';
354   }
355 
356   Total.print(Total, OS);
357   OS << "Total\n\n";
358   OS.flush();
359 
360   TimersToPrint.clear();
361 }
362 
363 /// print - Print any started timers in this group and zero them.
print(raw_ostream & OS)364 void TimerGroup::print(raw_ostream &OS) {
365   sys::SmartScopedLock<true> L(*TimerLock);
366 
367   // See if any of our timers were started, if so add them to TimersToPrint and
368   // reset them.
369   for (Timer *T = FirstTimer; T; T = T->Next) {
370     if (!T->Started) continue;
371     TimersToPrint.push_back(std::make_pair(T->Time, T->Name));
372 
373     // Clear out the time.
374     T->Started = 0;
375     T->Time = TimeRecord();
376   }
377 
378   // If any timers were started, print the group.
379   if (!TimersToPrint.empty())
380     PrintQueuedTimers(OS);
381 }
382 
383 /// printAll - This static method prints all timers and clears them all out.
printAll(raw_ostream & OS)384 void TimerGroup::printAll(raw_ostream &OS) {
385   sys::SmartScopedLock<true> L(*TimerLock);
386 
387   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
388     TG->print(OS);
389 }
390