1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
2 //
3 //                     The LLVM Compiler Infrastructure
4 //
5 // This file was developed by the LLVM research group and is distributed under
6 // the University of Illinois Open Source License. See LICENSE.TXT for details.
7 //
8 //===----------------------------------------------------------------------===//
9 //
10 // Interval Timing implementation.
11 //
12 //===----------------------------------------------------------------------===//
13 
14 #include "Support/Timer.h"
15 #include "Support/CommandLine.h"
16 #include "Config/sys/resource.h"
17 #include "Config/sys/time.h"
18 #include "Config/unistd.h"
19 #include "Config/malloc.h"
20 #include <iostream>
21 #include <algorithm>
22 #include <functional>
23 #include <fstream>
24 #include <map>
25 using namespace llvm;
26 
27 // GetLibSupportInfoOutputFile - Return a file stream to print our output on...
28 namespace llvm { extern std::ostream *GetLibSupportInfoOutputFile(); }
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 std::string &getLibSupportInfoOutputFilename() {
39   static std::string *LibSupportInfoOutputFilename = new std::string();
40   return *LibSupportInfoOutputFilename;
41 }
42 
43 namespace {
44 #ifdef HAVE_MALLINFO
45   cl::opt<bool>
46   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
47                                       "tracking (this may be slow)"),
48              cl::Hidden);
49 #endif
50 
51   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 static TimerGroup *DefaultTimerGroup = 0;
58 static TimerGroup *getDefaultTimerGroup() {
59   if (DefaultTimerGroup) return DefaultTimerGroup;
60   return DefaultTimerGroup = new TimerGroup("Miscellaneous Ungrouped Timers");
61 }
62 
63 Timer::Timer(const std::string &N)
64   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
65     Started(false), TG(getDefaultTimerGroup()) {
66   TG->addTimer();
67 }
68 
69 Timer::Timer(const std::string &N, TimerGroup &tg)
70   : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N),
71     Started(false), TG(&tg) {
72   TG->addTimer();
73 }
74 
75 Timer::Timer(const Timer &T) {
76   TG = T.TG;
77   if (TG) TG->addTimer();
78   operator=(T);
79 }
80 
81 
82 // Copy ctor, initialize with no TG member.
83 Timer::Timer(bool, const Timer &T) {
84   TG = T.TG;     // Avoid assertion in operator=
85   operator=(T);  // Copy contents
86   TG = 0;
87 }
88 
89 
90 Timer::~Timer() {
91   if (TG) {
92     if (Started) {
93       Started = false;
94       TG->addTimerToPrint(*this);
95     }
96     TG->removeTimer();
97   }
98 }
99 
100 static long getMemUsage() {
101 #ifdef HAVE_MALLINFO
102   if (TrackSpace) {
103     struct mallinfo MI = mallinfo();
104     return MI.uordblks/*+MI.hblkhd*/;
105   }
106 #endif
107   return 0;
108 }
109 
110 struct TimeRecord {
111   double Elapsed, UserTime, SystemTime;
112   long MemUsed;
113 };
114 
115 static TimeRecord getTimeRecord(bool Start) {
116   struct rusage RU;
117   struct timeval T;
118   long MemUsed = 0;
119   if (Start) {
120     MemUsed = getMemUsage();
121     if (getrusage(RUSAGE_SELF, &RU))
122       perror("getrusage call failed: -time-passes info incorrect!");
123   }
124   gettimeofday(&T, 0);
125 
126   if (!Start) {
127     if (getrusage(RUSAGE_SELF, &RU))
128       perror("getrusage call failed: -time-passes info incorrect!");
129     MemUsed = getMemUsage();
130   }
131 
132   TimeRecord Result;
133   Result.Elapsed    =           T.tv_sec +           T.tv_usec/1000000.0;
134   Result.UserTime   = RU.ru_utime.tv_sec + RU.ru_utime.tv_usec/1000000.0;
135   Result.SystemTime = RU.ru_stime.tv_sec + RU.ru_stime.tv_usec/1000000.0;
136   Result.MemUsed = MemUsed;
137 
138   return Result;
139 }
140 
141 static std::vector<Timer*> ActiveTimers;
142 
143 void Timer::startTimer() {
144   Started = true;
145   TimeRecord TR = getTimeRecord(true);
146   Elapsed    -= TR.Elapsed;
147   UserTime   -= TR.UserTime;
148   SystemTime -= TR.SystemTime;
149   MemUsed    -= TR.MemUsed;
150   PeakMemBase = TR.MemUsed;
151   ActiveTimers.push_back(this);
152 }
153 
154 void Timer::stopTimer() {
155   TimeRecord TR = getTimeRecord(false);
156   Elapsed    += TR.Elapsed;
157   UserTime   += TR.UserTime;
158   SystemTime += TR.SystemTime;
159   MemUsed    += TR.MemUsed;
160 
161   if (ActiveTimers.back() == this) {
162     ActiveTimers.pop_back();
163   } else {
164     std::vector<Timer*>::iterator I =
165       std::find(ActiveTimers.begin(), ActiveTimers.end(), this);
166     assert(I != ActiveTimers.end() && "stop but no startTimer?");
167     ActiveTimers.erase(I);
168   }
169 }
170 
171 void Timer::sum(const Timer &T) {
172   Elapsed    += T.Elapsed;
173   UserTime   += T.UserTime;
174   SystemTime += T.SystemTime;
175   MemUsed    += T.MemUsed;
176   PeakMem    += T.PeakMem;
177 }
178 
179 /// addPeakMemoryMeasurement - This method should be called whenever memory
180 /// usage needs to be checked.  It adds a peak memory measurement to the
181 /// currently active timers, which will be printed when the timer group prints
182 ///
183 void Timer::addPeakMemoryMeasurement() {
184   long MemUsed = getMemUsage();
185 
186   for (std::vector<Timer*>::iterator I = ActiveTimers.begin(),
187          E = ActiveTimers.end(); I != E; ++I)
188     (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase);
189 }
190 
191 //===----------------------------------------------------------------------===//
192 //   NamedRegionTimer Implementation
193 //===----------------------------------------------------------------------===//
194 
195 static Timer &getNamedRegionTimer(const std::string &Name) {
196   static std::map<std::string, Timer> NamedTimers;
197 
198   std::map<std::string, Timer>::iterator I = NamedTimers.lower_bound(Name);
199   if (I != NamedTimers.end() && I->first == Name)
200     return I->second;
201 
202   return NamedTimers.insert(I, std::make_pair(Name, Timer(Name)))->second;
203 }
204 
205 NamedRegionTimer::NamedRegionTimer(const std::string &Name)
206   : TimeRegion(getNamedRegionTimer(Name)) {}
207 
208 
209 //===----------------------------------------------------------------------===//
210 //   TimerGroup Implementation
211 //===----------------------------------------------------------------------===//
212 
213 // printAlignedFP - Simulate the printf "%A.Bf" format, where A is the
214 // TotalWidth size, and B is the AfterDec size.
215 //
216 static void printAlignedFP(double Val, unsigned AfterDec, unsigned TotalWidth,
217                            std::ostream &OS) {
218   assert(TotalWidth >= AfterDec+1 && "Bad FP Format!");
219   OS.width(TotalWidth-AfterDec-1);
220   char OldFill = OS.fill();
221   OS.fill(' ');
222   OS << (int)Val;  // Integer part;
223   OS << ".";
224   OS.width(AfterDec);
225   OS.fill('0');
226   unsigned ResultFieldSize = 1;
227   while (AfterDec--) ResultFieldSize *= 10;
228   OS << (int)(Val*ResultFieldSize) % ResultFieldSize;
229   OS.fill(OldFill);
230 }
231 
232 static void printVal(double Val, double Total, std::ostream &OS) {
233   if (Total < 1e-7)   // Avoid dividing by zero...
234     OS << "        -----     ";
235   else {
236     OS << "  ";
237     printAlignedFP(Val, 4, 7, OS);
238     OS << " (";
239     printAlignedFP(Val*100/Total, 1, 5, OS);
240     OS << "%)";
241   }
242 }
243 
244 void Timer::print(const Timer &Total, std::ostream &OS) {
245   if (Total.UserTime)
246     printVal(UserTime, Total.UserTime, OS);
247   if (Total.SystemTime)
248     printVal(SystemTime, Total.SystemTime, OS);
249   if (Total.getProcessTime())
250     printVal(getProcessTime(), Total.getProcessTime(), OS);
251   printVal(Elapsed, Total.Elapsed, OS);
252 
253   OS << "  ";
254 
255   if (Total.MemUsed) {
256     OS.width(9);
257     OS << MemUsed << "  ";
258   }
259   if (Total.PeakMem) {
260     if (PeakMem) {
261       OS.width(9);
262       OS << PeakMem << "  ";
263     } else
264       OS << "           ";
265   }
266   OS << Name << "\n";
267 
268   Started = false;  // Once printed, don't print again
269 }
270 
271 // GetLibSupportInfoOutputFile - Return a file stream to print our output on...
272 std::ostream *
273 llvm::GetLibSupportInfoOutputFile() {
274   std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename();
275   if (LibSupportInfoOutputFilename.empty())
276     return &std::cerr;
277   if (LibSupportInfoOutputFilename == "-")
278     return &std::cout;
279 
280   std::ostream *Result = new std::ofstream(LibSupportInfoOutputFilename.c_str(),
281                                            std::ios::app);
282   if (!Result->good()) {
283     std::cerr << "Error opening info-output-file '"
284               << LibSupportInfoOutputFilename << " for appending!\n";
285     delete Result;
286     return &std::cerr;
287   }
288   return Result;
289 }
290 
291 
292 void TimerGroup::removeTimer() {
293   if (--NumTimers == 0 && !TimersToPrint.empty()) { // Print timing report...
294     // Sort the timers in descending order by amount of time taken...
295     std::sort(TimersToPrint.begin(), TimersToPrint.end(),
296               std::greater<Timer>());
297 
298     // Figure out how many spaces to indent TimerGroup name...
299     unsigned Padding = (80-Name.length())/2;
300     if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
301 
302     std::ostream *OutStream = GetLibSupportInfoOutputFile();
303 
304     ++NumTimers;
305     {  // Scope to contain Total timer... don't allow total timer to drop us to
306        // zero timers...
307       Timer Total("TOTAL");
308 
309       for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
310         Total.sum(TimersToPrint[i]);
311 
312       // Print out timing header...
313       *OutStream << "===" << std::string(73, '-') << "===\n"
314                  << std::string(Padding, ' ') << Name << "\n"
315                  << "===" << std::string(73, '-')
316                  << "===\n  Total Execution Time: ";
317 
318       printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream);
319       *OutStream << " seconds (";
320       printAlignedFP(Total.getWallTime(), 4, 5, *OutStream);
321       *OutStream << " wall clock)\n\n";
322 
323       if (Total.UserTime)
324         *OutStream << "   ---User Time---";
325       if (Total.SystemTime)
326         *OutStream << "   --System Time--";
327       if (Total.getProcessTime())
328         *OutStream << "   --User+System--";
329       *OutStream << "   ---Wall Time---";
330       if (Total.getMemUsed())
331         *OutStream << "  ---Mem---";
332       if (Total.getPeakMem())
333         *OutStream << "  -PeakMem-";
334       *OutStream << "  --- Name ---\n";
335 
336       // Loop through all of the timing data, printing it out...
337       for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
338         TimersToPrint[i].print(Total, *OutStream);
339 
340       Total.print(Total, *OutStream);
341       *OutStream << std::endl;  // Flush output
342     }
343     --NumTimers;
344 
345     TimersToPrint.clear();
346 
347     if (OutStream != &std::cerr && OutStream != &std::cout)
348       delete OutStream;   // Close the file...
349   }
350 
351   // Delete default timer group!
352   if (NumTimers == 0 && this == DefaultTimerGroup) {
353     delete DefaultTimerGroup;
354     DefaultTimerGroup = 0;
355   }
356 }
357 
358