Line data Source code
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 : /// \file Interval Timing implementation.
11 : //
12 : //===----------------------------------------------------------------------===//
13 :
14 : #include "llvm/Support/Timer.h"
15 : #include "llvm/ADT/Statistic.h"
16 : #include "llvm/ADT/StringMap.h"
17 : #include "llvm/Support/CommandLine.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/Process.h"
23 : #include "llvm/Support/YAMLTraits.h"
24 : #include "llvm/Support/raw_ostream.h"
25 : #include <limits>
26 :
27 : using namespace llvm;
28 :
29 : // This ugly hack is brought to you courtesy of constructor/destructor ordering
30 : // being unspecified by C++. Basically the problem is that a Statistic object
31 : // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
32 : // (below), which calls this function. LibSupportInfoOutputFilename used to be
33 : // a global variable, but sometimes it would get destroyed before the Statistic,
34 : // causing havoc to ensue. We "fix" this by creating the string the first time
35 : // it is needed and never destroying it.
36 : static ManagedStatic<std::string> LibSupportInfoOutputFilename;
37 : static std::string &getLibSupportInfoOutputFilename() {
38 45 : return *LibSupportInfoOutputFilename;
39 : }
40 :
41 : static ManagedStatic<sys::SmartMutex<true> > TimerLock;
42 :
43 : namespace {
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 45 : std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
56 : const std::string &OutputFilename = getLibSupportInfoOutputFilename();
57 45 : if (OutputFilename.empty())
58 45 : return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
59 0 : if (OutputFilename == "-")
60 0 : return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
61 :
62 : // Append mode is used because the info output file is opened and closed
63 : // each time -stats or -time-passes wants to print output to it. To
64 : // compensate for this, the test-suite Makefiles have code to delete the
65 : // info output file before running commands which write to it.
66 : std::error_code EC;
67 : auto Result = llvm::make_unique<raw_fd_ostream>(
68 0 : OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
69 0 : if (!EC)
70 : return Result;
71 :
72 0 : errs() << "Error opening info-output-file '"
73 0 : << OutputFilename << " for appending!\n";
74 0 : return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
75 : }
76 :
77 : namespace {
78 : struct CreateDefaultTimerGroup {
79 14866 : static void *call() {
80 14866 : return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
81 : }
82 : };
83 : } // namespace
84 : static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
85 29595 : static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
86 :
87 : //===----------------------------------------------------------------------===//
88 : // Timer Implementation
89 : //===----------------------------------------------------------------------===//
90 :
91 29527 : void Timer::init(StringRef Name, StringRef Description) {
92 29527 : init(Name, Description, *getDefaultTimerGroup());
93 29527 : }
94 :
95 30901 : void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
96 : assert(!TG && "Timer already initialized");
97 30901 : this->Name.assign(Name.begin(), Name.end());
98 30901 : this->Description.assign(Description.begin(), Description.end());
99 30901 : Running = Triggered = false;
100 30901 : TG = &tg;
101 30901 : TG->addTimer(*this);
102 30901 : }
103 :
104 30893 : Timer::~Timer() {
105 32986 : if (!TG) return; // Never initialized, or already cleared.
106 30893 : TG->removeTimer(*this);
107 32986 : }
108 :
109 : static inline size_t getMemUsage() {
110 5752 : if (!TrackSpace) return 0;
111 0 : return sys::Process::GetMallocUsage();
112 : }
113 :
114 5752 : TimeRecord TimeRecord::getCurrentTime(bool Start) {
115 : using Seconds = std::chrono::duration<double, std::ratio<1>>;
116 : TimeRecord Result;
117 5752 : sys::TimePoint<> now;
118 : std::chrono::nanoseconds user, sys;
119 :
120 5752 : if (Start) {
121 2923 : Result.MemUsed = getMemUsage();
122 2923 : sys::Process::GetTimeUsage(now, user, sys);
123 : } else {
124 2829 : sys::Process::GetTimeUsage(now, user, sys);
125 2829 : Result.MemUsed = getMemUsage();
126 : }
127 :
128 5752 : Result.WallTime = Seconds(now.time_since_epoch()).count();
129 5752 : Result.UserTime = Seconds(user).count();
130 5752 : Result.SystemTime = Seconds(sys).count();
131 5752 : return Result;
132 : }
133 :
134 2829 : void Timer::startTimer() {
135 : assert(!Running && "Cannot start a running timer");
136 2829 : Running = Triggered = true;
137 2829 : StartTime = TimeRecord::getCurrentTime(true);
138 2829 : }
139 :
140 2829 : void Timer::stopTimer() {
141 : assert(Running && "Cannot stop a paused timer");
142 2829 : Running = false;
143 2829 : Time += TimeRecord::getCurrentTime(false);
144 : Time -= StartTime;
145 2829 : }
146 :
147 1 : void Timer::clear() {
148 1 : Running = Triggered = false;
149 1 : Time = StartTime = TimeRecord();
150 1 : }
151 :
152 7319 : static void printVal(double Val, double Total, raw_ostream &OS) {
153 7319 : if (Total < 1e-7) // Avoid dividing by zero.
154 0 : OS << " ----- ";
155 : else
156 14638 : OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total);
157 7319 : }
158 :
159 2492 : void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
160 2492 : if (Total.getUserTime())
161 2295 : printVal(getUserTime(), Total.getUserTime(), OS);
162 2492 : if (Total.getSystemTime())
163 164 : printVal(getSystemTime(), Total.getSystemTime(), OS);
164 4984 : if (Total.getProcessTime())
165 4736 : printVal(getProcessTime(), Total.getProcessTime(), OS);
166 2492 : printVal(getWallTime(), Total.getWallTime(), OS);
167 :
168 2492 : OS << " ";
169 :
170 2492 : if (Total.getMemUsed())
171 0 : OS << format("%9" PRId64 " ", (int64_t)getMemUsed());
172 2492 : }
173 :
174 :
175 : //===----------------------------------------------------------------------===//
176 : // NamedRegionTimer Implementation
177 : //===----------------------------------------------------------------------===//
178 :
179 : namespace {
180 :
181 : typedef StringMap<Timer> Name2TimerMap;
182 :
183 : class Name2PairMap {
184 : StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
185 : public:
186 10 : ~Name2PairMap() {
187 : for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
188 25 : I = Map.begin(), E = Map.end(); I != E; ++I)
189 5 : delete I->second.first;
190 10 : }
191 :
192 5 : Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
193 : StringRef GroupDescription) {
194 5 : sys::SmartScopedLock<true> L(*TimerLock);
195 :
196 5 : std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
197 :
198 5 : if (!GroupEntry.first)
199 5 : GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
200 :
201 5 : Timer &T = GroupEntry.second[Name];
202 5 : if (!T.isInitialized())
203 5 : T.init(Name, Description, *GroupEntry.first);
204 5 : return T;
205 : }
206 : };
207 :
208 : }
209 :
210 : static ManagedStatic<Name2PairMap> NamedGroupedTimers;
211 :
212 23370118 : NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
213 : StringRef GroupName,
214 23370118 : StringRef GroupDescription, bool Enabled)
215 : : TimeRegion(!Enabled ? nullptr
216 : : &NamedGroupedTimers->get(Name, Description, GroupName,
217 23370123 : GroupDescription)) {}
218 :
219 : //===----------------------------------------------------------------------===//
220 : // TimerGroup Implementation
221 : //===----------------------------------------------------------------------===//
222 :
223 : /// This is the global list of TimerGroups, maintained by the TimerGroup
224 : /// ctor/dtor and is protected by the TimerLock lock.
225 : static TimerGroup *TimerGroupList = nullptr;
226 :
227 15838 : TimerGroup::TimerGroup(StringRef Name, StringRef Description)
228 : : Name(Name.begin(), Name.end()),
229 15838 : Description(Description.begin(), Description.end()) {
230 : // Add the group to TimerGroupList.
231 15838 : sys::SmartScopedLock<true> L(*TimerLock);
232 15838 : if (TimerGroupList)
233 42 : TimerGroupList->Prev = &Next;
234 15838 : Next = TimerGroupList;
235 15838 : Prev = &TimerGroupList;
236 15838 : TimerGroupList = this;
237 15838 : }
238 :
239 5 : TimerGroup::TimerGroup(StringRef Name, StringRef Description,
240 5 : const StringMap<TimeRecord> &Records)
241 5 : : TimerGroup(Name, Description) {
242 5 : TimersToPrint.reserve(Records.size());
243 15 : for (const auto &P : Records)
244 15 : TimersToPrint.emplace_back(P.getValue(), P.getKey(), P.getKey());
245 : assert(TimersToPrint.size() == Records.size() && "Size mismatch");
246 5 : }
247 :
248 31642 : TimerGroup::~TimerGroup() {
249 : // If the timer group is destroyed before the timers it owns, accumulate and
250 : // print the timing data.
251 15826 : while (FirstTimer)
252 5 : removeTimer(*FirstTimer);
253 :
254 : // Remove the group from the TimerGroupList.
255 15821 : sys::SmartScopedLock<true> L(*TimerLock);
256 15821 : *Prev = Next;
257 15821 : if (Next)
258 25 : Next->Prev = Prev;
259 15821 : }
260 :
261 :
262 30898 : void TimerGroup::removeTimer(Timer &T) {
263 30898 : sys::SmartScopedLock<true> L(*TimerLock);
264 :
265 : // If the timer was started, move its data to TimersToPrint.
266 30898 : if (T.hasTriggered())
267 1391 : TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
268 :
269 30898 : T.TG = nullptr;
270 :
271 : // Unlink the timer from our list.
272 30898 : *T.Prev = T.Next;
273 30898 : if (T.Next)
274 15957 : T.Next->Prev = T.Prev;
275 :
276 : // Print the report when all timers in this group are destroyed if some of
277 : // them were started.
278 30898 : if (FirstTimer || TimersToPrint.empty())
279 : return;
280 :
281 45 : std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
282 45 : PrintQueuedTimers(*OutStream);
283 : }
284 :
285 30901 : void TimerGroup::addTimer(Timer &T) {
286 30901 : sys::SmartScopedLock<true> L(*TimerLock);
287 :
288 : // Add the timer to our list.
289 30901 : if (FirstTimer)
290 16004 : FirstTimer->Prev = &T.Next;
291 30901 : T.Next = FirstTimer;
292 30901 : T.Prev = &FirstTimer;
293 30901 : FirstTimer = &T;
294 30901 : }
295 :
296 68 : void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
297 : // Sort the timers in descending order by amount of time taken.
298 : llvm::sort(TimersToPrint);
299 :
300 : TimeRecord Total;
301 2474 : for (const PrintRecord &Record : TimersToPrint)
302 : Total += Record.Time;
303 :
304 : // Print out timing header.
305 136 : OS << "===" << std::string(73, '-') << "===\n";
306 : // Figure out how many spaces to indent TimerGroup name.
307 68 : unsigned Padding = (80-Description.length())/2;
308 68 : if (Padding > 80) Padding = 0; // Don't allow "negative" numbers
309 68 : OS.indent(Padding) << Description << '\n';
310 204 : OS << "===" << std::string(73, '-') << "===\n";
311 :
312 : // If this is not an collection of ungrouped times, print the total time.
313 : // Ungrouped timers don't really make sense to add up. We still print the
314 : // TOTAL line to make the percentages make sense.
315 68 : if (this != getDefaultTimerGroup())
316 57 : OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
317 114 : Total.getProcessTime(), Total.getWallTime());
318 : OS << '\n';
319 :
320 68 : if (Total.getUserTime())
321 47 : OS << " ---User Time---";
322 68 : if (Total.getSystemTime())
323 36 : OS << " --System Time--";
324 136 : if (Total.getProcessTime())
325 54 : OS << " --User+System--";
326 68 : OS << " ---Wall Time---";
327 68 : if (Total.getMemUsed())
328 0 : OS << " ---Mem---";
329 68 : OS << " --- Name ---\n";
330 :
331 : // Loop through all of the timing data, printing it out.
332 : for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
333 2474 : TimersToPrint.rend())) {
334 2406 : Record.Time.print(Total, OS);
335 : OS << Record.Description << '\n';
336 : }
337 :
338 68 : Total.print(Total, OS);
339 68 : OS << "Total\n\n";
340 : OS.flush();
341 :
342 : TimersToPrint.clear();
343 68 : }
344 :
345 14874 : void TimerGroup::prepareToPrintList() {
346 : // See if any of our timers were started, if so add them to TimersToPrint.
347 15886 : for (Timer *T = FirstTimer; T; T = T->Next) {
348 1012 : if (!T->hasTriggered()) continue;
349 1012 : bool WasRunning = T->isRunning();
350 1012 : if (WasRunning)
351 0 : T->stopTimer();
352 :
353 1012 : TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
354 :
355 1012 : if (WasRunning)
356 0 : T->startTimer();
357 : }
358 14874 : }
359 :
360 14871 : void TimerGroup::print(raw_ostream &OS) {
361 14871 : sys::SmartScopedLock<true> L(*TimerLock);
362 :
363 14871 : prepareToPrintList();
364 :
365 : // If any timers were started, print the group.
366 14871 : if (!TimersToPrint.empty())
367 23 : PrintQueuedTimers(OS);
368 14871 : }
369 :
370 0 : void TimerGroup::clear() {
371 0 : sys::SmartScopedLock<true> L(*TimerLock);
372 0 : for (Timer *T = FirstTimer; T; T = T->Next)
373 0 : T->clear();
374 0 : }
375 :
376 48042 : void TimerGroup::printAll(raw_ostream &OS) {
377 48042 : sys::SmartScopedLock<true> L(*TimerLock);
378 :
379 62910 : for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
380 14868 : TG->print(OS);
381 48042 : }
382 :
383 0 : void TimerGroup::clearAll() {
384 0 : sys::SmartScopedLock<true> L(*TimerLock);
385 0 : for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
386 0 : TG->clear();
387 0 : }
388 :
389 6 : void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
390 : const char *suffix, double Value) {
391 : assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
392 : "TimerGroup name should not need quotes");
393 : assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
394 : "Timer name should not need quotes");
395 : constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
396 12 : OS << "\t\"time." << Name << '.' << R.Name << suffix
397 6 : << "\": " << format("%.*e", max_digits10 - 1, Value);
398 6 : }
399 :
400 3 : const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
401 3 : sys::SmartScopedLock<true> L(*TimerLock);
402 :
403 3 : prepareToPrintList();
404 5 : for (const PrintRecord &R : TimersToPrint) {
405 2 : OS << delim;
406 : delim = ",\n";
407 :
408 : const TimeRecord &T = R.Time;
409 2 : printJSONValue(OS, R, ".wall", T.getWallTime());
410 2 : OS << delim;
411 2 : printJSONValue(OS, R, ".user", T.getUserTime());
412 2 : OS << delim;
413 2 : printJSONValue(OS, R, ".sys", T.getSystemTime());
414 2 : if (T.getMemUsed()) {
415 0 : OS << delim;
416 0 : printJSONValue(OS, R, ".mem", T.getMemUsed());
417 : }
418 : }
419 : TimersToPrint.clear();
420 3 : return delim;
421 : }
422 :
423 1 : const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
424 1 : sys::SmartScopedLock<true> L(*TimerLock);
425 2 : for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
426 1 : delim = TG->printJSONValues(OS, delim);
427 1 : return delim;
428 : }
429 :
430 6 : void TimerGroup::ConstructTimerLists() {
431 6 : (void)*NamedGroupedTimers;
432 6 : }
|
