1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
2 //
3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4 // See https://llvm.org/LICENSE.txt for license information.
5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6 //
7 //===----------------------------------------------------------------------===//
8 //
9 /// \file Interval Timing implementation.
10 //
11 //===----------------------------------------------------------------------===//
12 
13 #include "llvm/Support/Timer.h"
14 
15 #include "DebugOptions.h"
16 
17 #include "llvm/ADT/Statistic.h"
18 #include "llvm/ADT/StringMap.h"
19 #include "llvm/Config/config.h"
20 #include "llvm/Support/CommandLine.h"
21 #include "llvm/Support/FileSystem.h"
22 #include "llvm/Support/Format.h"
23 #include "llvm/Support/ManagedStatic.h"
24 #include "llvm/Support/Mutex.h"
25 #include "llvm/Support/Process.h"
26 #include "llvm/Support/Signposts.h"
27 #include "llvm/Support/YAMLTraits.h"
28 #include "llvm/Support/raw_ostream.h"
29 #include <limits>
30 
31 #if HAVE_UNISTD_H
32 #include <unistd.h>
33 #endif
34 
35 #ifdef HAVE_PROC_PID_RUSAGE
36 #include <libproc.h>
37 #endif
38 
39 using namespace llvm;
40 
41 // This ugly hack is brought to you courtesy of constructor/destructor ordering
42 // being unspecified by C++.  Basically the problem is that a Statistic object
43 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
44 // (below), which calls this function.  LibSupportInfoOutputFilename used to be
45 // a global variable, but sometimes it would get destroyed before the Statistic,
46 // causing havoc to ensue.  We "fix" this by creating the string the first time
47 // it is needed and never destroying it.
48 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
49 static std::string &getLibSupportInfoOutputFilename() {
50   return *LibSupportInfoOutputFilename;
51 }
52 
53 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
54 
55 /// Allows llvm::Timer to emit signposts when supported.
56 static ManagedStatic<SignpostEmitter> Signposts;
57 
58 namespace {
59 struct CreateTrackSpace {
60   static void *call() {
61     return new cl::opt<bool>("track-memory",
62                              cl::desc("Enable -time-passes memory "
63                                       "tracking (this may be slow)"),
64                              cl::Hidden);
65   }
66 };
67 static ManagedStatic<cl::opt<bool>, CreateTrackSpace> TrackSpace;
68 struct CreateInfoOutputFilename {
69   static void *call() {
70     return new cl::opt<std::string, true>(
71         "info-output-file", cl::value_desc("filename"),
72         cl::desc("File to append -stats and -timer output to"), cl::Hidden,
73         cl::location(getLibSupportInfoOutputFilename()));
74   }
75 };
76 static ManagedStatic<cl::opt<std::string, true>, CreateInfoOutputFilename>
77     InfoOutputFilename;
78 struct CreateSortTimers {
79   static void *call() {
80     return new cl::opt<bool>(
81         "sort-timers",
82         cl::desc("In the report, sort the timers in each group "
83                  "in wall clock time order"),
84         cl::init(true), cl::Hidden);
85   }
86 };
87 ManagedStatic<cl::opt<bool>, CreateSortTimers> SortTimers;
88 } // namespace
89 
90 void llvm::initTimerOptions() {
91   *TrackSpace;
92   *InfoOutputFilename;
93   *SortTimers;
94 }
95 
96 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
97   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
98   if (OutputFilename.empty())
99     return std::make_unique<raw_fd_ostream>(2, false); // stderr.
100   if (OutputFilename == "-")
101     return std::make_unique<raw_fd_ostream>(1, false); // stdout.
102 
103   // Append mode is used because the info output file is opened and closed
104   // each time -stats or -time-passes wants to print output to it. To
105   // compensate for this, the test-suite Makefiles have code to delete the
106   // info output file before running commands which write to it.
107   std::error_code EC;
108   auto Result = std::make_unique<raw_fd_ostream>(
109       OutputFilename, EC, sys::fs::OF_Append | sys::fs::OF_TextWithCRLF);
110   if (!EC)
111     return Result;
112 
113   errs() << "Error opening info-output-file '"
114     << OutputFilename << " for appending!\n";
115   return std::make_unique<raw_fd_ostream>(2, false); // stderr.
116 }
117 
118 namespace {
119 struct CreateDefaultTimerGroup {
120   static void *call() {
121     return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
122   }
123 };
124 } // namespace
125 static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
126 static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
127 
128 //===----------------------------------------------------------------------===//
129 // Timer Implementation
130 //===----------------------------------------------------------------------===//
131 
132 void Timer::init(StringRef TimerName, StringRef TimerDescription) {
133   init(TimerName, TimerDescription, *getDefaultTimerGroup());
134 }
135 
136 void Timer::init(StringRef TimerName, StringRef TimerDescription,
137                  TimerGroup &tg) {
138   assert(!TG && "Timer already initialized");
139   Name.assign(TimerName.begin(), TimerName.end());
140   Description.assign(TimerDescription.begin(), TimerDescription.end());
141   Running = Triggered = false;
142   TG = &tg;
143   TG->addTimer(*this);
144 }
145 
146 Timer::~Timer() {
147   if (!TG) return;  // Never initialized, or already cleared.
148   TG->removeTimer(*this);
149 }
150 
151 static inline size_t getMemUsage() {
152   if (!*TrackSpace)
153     return 0;
154   return sys::Process::GetMallocUsage();
155 }
156 
157 static uint64_t getCurInstructionsExecuted() {
158 #if defined(HAVE_UNISTD_H) && defined(HAVE_PROC_PID_RUSAGE) &&                 \
159     defined(RUSAGE_INFO_V4)
160   struct rusage_info_v4 ru;
161   if (proc_pid_rusage(getpid(), RUSAGE_INFO_V4, (rusage_info_t *)&ru) == 0) {
162     return ru.ri_instructions;
163   }
164 #endif
165   return 0;
166 }
167 
168 TimeRecord TimeRecord::getCurrentTime(bool Start) {
169   using Seconds = std::chrono::duration<double, std::ratio<1>>;
170   TimeRecord Result;
171   sys::TimePoint<> now;
172   std::chrono::nanoseconds user, sys;
173 
174   if (Start) {
175     Result.MemUsed = getMemUsage();
176     Result.InstructionsExecuted = getCurInstructionsExecuted();
177     sys::Process::GetTimeUsage(now, user, sys);
178   } else {
179     sys::Process::GetTimeUsage(now, user, sys);
180     Result.InstructionsExecuted = getCurInstructionsExecuted();
181     Result.MemUsed = getMemUsage();
182   }
183 
184   Result.WallTime = Seconds(now.time_since_epoch()).count();
185   Result.UserTime = Seconds(user).count();
186   Result.SystemTime = Seconds(sys).count();
187   return Result;
188 }
189 
190 void Timer::startTimer() {
191   assert(!Running && "Cannot start a running timer");
192   Running = Triggered = true;
193   Signposts->startInterval(this, getName());
194   StartTime = TimeRecord::getCurrentTime(true);
195 }
196 
197 void Timer::stopTimer() {
198   assert(Running && "Cannot stop a paused timer");
199   Running = false;
200   Time += TimeRecord::getCurrentTime(false);
201   Time -= StartTime;
202   Signposts->endInterval(this, getName());
203 }
204 
205 void Timer::clear() {
206   Running = Triggered = false;
207   Time = StartTime = TimeRecord();
208 }
209 
210 static void printVal(double Val, double Total, raw_ostream &OS) {
211   if (Total < 1e-7)   // Avoid dividing by zero.
212     OS << "        -----     ";
213   else
214     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
215 }
216 
217 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
218   if (Total.getUserTime())
219     printVal(getUserTime(), Total.getUserTime(), OS);
220   if (Total.getSystemTime())
221     printVal(getSystemTime(), Total.getSystemTime(), OS);
222   if (Total.getProcessTime())
223     printVal(getProcessTime(), Total.getProcessTime(), OS);
224   printVal(getWallTime(), Total.getWallTime(), OS);
225 
226   OS << "  ";
227 
228   if (Total.getMemUsed())
229     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
230   if (Total.getInstructionsExecuted())
231     OS << format("%9" PRId64 "  ", (int64_t)getInstructionsExecuted());
232 }
233 
234 
235 //===----------------------------------------------------------------------===//
236 //   NamedRegionTimer Implementation
237 //===----------------------------------------------------------------------===//
238 
239 namespace {
240 
241 typedef StringMap<Timer> Name2TimerMap;
242 
243 class Name2PairMap {
244   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
245 public:
246   ~Name2PairMap() {
247     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
248          I = Map.begin(), E = Map.end(); I != E; ++I)
249       delete I->second.first;
250   }
251 
252   Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
253              StringRef GroupDescription) {
254     sys::SmartScopedLock<true> L(*TimerLock);
255 
256     std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
257 
258     if (!GroupEntry.first)
259       GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
260 
261     Timer &T = GroupEntry.second[Name];
262     if (!T.isInitialized())
263       T.init(Name, Description, *GroupEntry.first);
264     return T;
265   }
266 };
267 
268 }
269 
270 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
271 
272 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
273                                    StringRef GroupName,
274                                    StringRef GroupDescription, bool Enabled)
275   : TimeRegion(!Enabled ? nullptr
276                  : &NamedGroupedTimers->get(Name, Description, GroupName,
277                                             GroupDescription)) {}
278 
279 //===----------------------------------------------------------------------===//
280 //   TimerGroup Implementation
281 //===----------------------------------------------------------------------===//
282 
283 /// This is the global list of TimerGroups, maintained by the TimerGroup
284 /// ctor/dtor and is protected by the TimerLock lock.
285 static TimerGroup *TimerGroupList = nullptr;
286 
287 TimerGroup::TimerGroup(StringRef Name, StringRef Description)
288   : Name(Name.begin(), Name.end()),
289     Description(Description.begin(), Description.end()) {
290   // Add the group to TimerGroupList.
291   sys::SmartScopedLock<true> L(*TimerLock);
292   if (TimerGroupList)
293     TimerGroupList->Prev = &Next;
294   Next = TimerGroupList;
295   Prev = &TimerGroupList;
296   TimerGroupList = this;
297 }
298 
299 TimerGroup::TimerGroup(StringRef Name, StringRef Description,
300                        const StringMap<TimeRecord> &Records)
301     : TimerGroup(Name, Description) {
302   TimersToPrint.reserve(Records.size());
303   for (const auto &P : Records)
304     TimersToPrint.emplace_back(P.getValue(), std::string(P.getKey()),
305                                std::string(P.getKey()));
306   assert(TimersToPrint.size() == Records.size() && "Size mismatch");
307 }
308 
309 TimerGroup::~TimerGroup() {
310   // If the timer group is destroyed before the timers it owns, accumulate and
311   // print the timing data.
312   while (FirstTimer)
313     removeTimer(*FirstTimer);
314 
315   // Remove the group from the TimerGroupList.
316   sys::SmartScopedLock<true> L(*TimerLock);
317   *Prev = Next;
318   if (Next)
319     Next->Prev = Prev;
320 }
321 
322 
323 void TimerGroup::removeTimer(Timer &T) {
324   sys::SmartScopedLock<true> L(*TimerLock);
325 
326   // If the timer was started, move its data to TimersToPrint.
327   if (T.hasTriggered())
328     TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
329 
330   T.TG = nullptr;
331 
332   // Unlink the timer from our list.
333   *T.Prev = T.Next;
334   if (T.Next)
335     T.Next->Prev = T.Prev;
336 
337   // Print the report when all timers in this group are destroyed if some of
338   // them were started.
339   if (FirstTimer || TimersToPrint.empty())
340     return;
341 
342   std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
343   PrintQueuedTimers(*OutStream);
344 }
345 
346 void TimerGroup::addTimer(Timer &T) {
347   sys::SmartScopedLock<true> L(*TimerLock);
348 
349   // Add the timer to our list.
350   if (FirstTimer)
351     FirstTimer->Prev = &T.Next;
352   T.Next = FirstTimer;
353   T.Prev = &FirstTimer;
354   FirstTimer = &T;
355 }
356 
357 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
358   // Perhaps sort the timers in descending order by amount of time taken.
359   if (*SortTimers)
360     llvm::sort(TimersToPrint);
361 
362   TimeRecord Total;
363   for (const PrintRecord &Record : TimersToPrint)
364     Total += Record.Time;
365 
366   // Print out timing header.
367   OS << "===" << std::string(73, '-') << "===\n";
368   // Figure out how many spaces to indent TimerGroup name.
369   unsigned Padding = (80-Description.length())/2;
370   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
371   OS.indent(Padding) << Description << '\n';
372   OS << "===" << std::string(73, '-') << "===\n";
373 
374   // If this is not an collection of ungrouped times, print the total time.
375   // Ungrouped timers don't really make sense to add up.  We still print the
376   // TOTAL line to make the percentages make sense.
377   if (this != getDefaultTimerGroup())
378     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
379                  Total.getProcessTime(), Total.getWallTime());
380   OS << '\n';
381 
382   if (Total.getUserTime())
383     OS << "   ---User Time---";
384   if (Total.getSystemTime())
385     OS << "   --System Time--";
386   if (Total.getProcessTime())
387     OS << "   --User+System--";
388   OS << "   ---Wall Time---";
389   if (Total.getMemUsed())
390     OS << "  ---Mem---";
391   if (Total.getInstructionsExecuted())
392     OS << "  ---Instr---";
393   OS << "  --- Name ---\n";
394 
395   // Loop through all of the timing data, printing it out.
396   for (const PrintRecord &Record : llvm::reverse(TimersToPrint)) {
397     Record.Time.print(Total, OS);
398     OS << Record.Description << '\n';
399   }
400 
401   Total.print(Total, OS);
402   OS << "Total\n\n";
403   OS.flush();
404 
405   TimersToPrint.clear();
406 }
407 
408 void TimerGroup::prepareToPrintList(bool ResetTime) {
409   // See if any of our timers were started, if so add them to TimersToPrint.
410   for (Timer *T = FirstTimer; T; T = T->Next) {
411     if (!T->hasTriggered()) continue;
412     bool WasRunning = T->isRunning();
413     if (WasRunning)
414       T->stopTimer();
415 
416     TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
417 
418     if (ResetTime)
419       T->clear();
420 
421     if (WasRunning)
422       T->startTimer();
423   }
424 }
425 
426 void TimerGroup::print(raw_ostream &OS, bool ResetAfterPrint) {
427   {
428     // After preparing the timers we can free the lock
429     sys::SmartScopedLock<true> L(*TimerLock);
430     prepareToPrintList(ResetAfterPrint);
431   }
432 
433   // If any timers were started, print the group.
434   if (!TimersToPrint.empty())
435     PrintQueuedTimers(OS);
436 }
437 
438 void TimerGroup::clear() {
439   sys::SmartScopedLock<true> L(*TimerLock);
440   for (Timer *T = FirstTimer; T; T = T->Next)
441     T->clear();
442 }
443 
444 void TimerGroup::printAll(raw_ostream &OS) {
445   sys::SmartScopedLock<true> L(*TimerLock);
446 
447   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
448     TG->print(OS);
449 }
450 
451 void TimerGroup::clearAll() {
452   sys::SmartScopedLock<true> L(*TimerLock);
453   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
454     TG->clear();
455 }
456 
457 void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
458                                 const char *suffix, double Value) {
459   assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
460          "TimerGroup name should not need quotes");
461   assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
462          "Timer name should not need quotes");
463   constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
464   OS << "\t\"time." << Name << '.' << R.Name << suffix
465      << "\": " << format("%.*e", max_digits10 - 1, Value);
466 }
467 
468 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
469   sys::SmartScopedLock<true> L(*TimerLock);
470 
471   prepareToPrintList(false);
472   for (const PrintRecord &R : TimersToPrint) {
473     OS << delim;
474     delim = ",\n";
475 
476     const TimeRecord &T = R.Time;
477     printJSONValue(OS, R, ".wall", T.getWallTime());
478     OS << delim;
479     printJSONValue(OS, R, ".user", T.getUserTime());
480     OS << delim;
481     printJSONValue(OS, R, ".sys", T.getSystemTime());
482     if (T.getMemUsed()) {
483       OS << delim;
484       printJSONValue(OS, R, ".mem", T.getMemUsed());
485     }
486     if (T.getInstructionsExecuted()) {
487       OS << delim;
488       printJSONValue(OS, R, ".instr", T.getInstructionsExecuted());
489     }
490   }
491   TimersToPrint.clear();
492   return delim;
493 }
494 
495 const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
496   sys::SmartScopedLock<true> L(*TimerLock);
497   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
498     delim = TG->printJSONValues(OS, delim);
499   return delim;
500 }
501 
502 void TimerGroup::constructForStatistics() {
503   (void)getLibSupportInfoOutputFilename();
504   (void)*NamedGroupedTimers;
505 }
506 
507 std::unique_ptr<TimerGroup> TimerGroup::aquireDefaultGroup() {
508   return std::unique_ptr<TimerGroup>(DefaultTimerGroup.claim());
509 }
510