Coverage Report

Created: 2019-07-24 05:18

/Users/buildslave/jenkins/workspace/clang-stage2-coverage-R/llvm/lib/Support/Timer.cpp
Line
Count
Source (jump to first uncovered line)
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
#include "llvm/ADT/Statistic.h"
15
#include "llvm/ADT/StringMap.h"
16
#include "llvm/Support/CommandLine.h"
17
#include "llvm/Support/FileSystem.h"
18
#include "llvm/Support/Format.h"
19
#include "llvm/Support/ManagedStatic.h"
20
#include "llvm/Support/Mutex.h"
21
#include "llvm/Support/Process.h"
22
#include "llvm/Support/Signposts.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
126k
static std::string &getLibSupportInfoOutputFilename() {
38
126k
  return *LibSupportInfoOutputFilename;
39
126k
}
40
41
static ManagedStatic<sys::SmartMutex<true> > TimerLock;
42
43
/// Allows llvm::Timer to emit signposts when supported.
44
static ManagedStatic<SignpostEmitter> Signposts;
45
46
namespace {
47
  static cl::opt<bool>
48
  TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
49
                                      "tracking (this may be slow)"),
50
             cl::Hidden);
51
52
  static cl::opt<std::string, true>
53
  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
54
                     cl::desc("File to append -stats and -timer output to"),
55
                   cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
56
}
57
58
53
std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
59
53
  const std::string &OutputFilename = getLibSupportInfoOutputFilename();
60
53
  if (OutputFilename.empty())
61
45
    return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
62
8
  if (OutputFilename == "-")
63
4
    return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
64
4
65
4
  // Append mode is used because the info output file is opened and closed
66
4
  // each time -stats or -time-passes wants to print output to it. To
67
4
  // compensate for this, the test-suite Makefiles have code to delete the
68
4
  // info output file before running commands which write to it.
69
4
  std::error_code EC;
70
4
  auto Result = llvm::make_unique<raw_fd_ostream>(
71
4
      OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
72
4
  if (!EC)
73
4
    return Result;
74
0
75
0
  errs() << "Error opening info-output-file '"
76
0
    << OutputFilename << " for appending!\n";
77
0
  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
78
0
}
79
80
namespace {
81
struct CreateDefaultTimerGroup {
82
21.7k
  static void *call() {
83
21.7k
    return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
84
21.7k
  }
85
};
86
} // namespace
87
static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
88
39.1k
static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
89
90
//===----------------------------------------------------------------------===//
91
// Timer Implementation
92
//===----------------------------------------------------------------------===//
93
94
39.0k
void Timer::init(StringRef Name, StringRef Description) {
95
39.0k
  init(Name, Description, *getDefaultTimerGroup());
96
39.0k
}
97
98
41.4k
void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
99
41.4k
  assert(!TG && "Timer already initialized");
100
41.4k
  this->Name.assign(Name.begin(), Name.end());
101
41.4k
  this->Description.assign(Description.begin(), Description.end());
102
41.4k
  Running = Triggered = false;
103
41.4k
  TG = &tg;
104
41.4k
  TG->addTimer(*this);
105
41.4k
}
106
107
43.6k
Timer::~Timer() {
108
43.6k
  if (!TG) 
return2.17k
; // Never initialized, or already cleared.
109
41.4k
  TG->removeTimer(*this);
110
41.4k
}
111
112
10.8k
static inline size_t getMemUsage() {
113
10.8k
  if (!TrackSpace) return 0;
114
0
  return sys::Process::GetMallocUsage();
115
0
}
116
117
10.8k
TimeRecord TimeRecord::getCurrentTime(bool Start) {
118
10.8k
  using Seconds = std::chrono::duration<double, std::ratio<1>>;
119
10.8k
  TimeRecord Result;
120
10.8k
  sys::TimePoint<> now;
121
10.8k
  std::chrono::nanoseconds user, sys;
122
10.8k
123
10.8k
  if (Start) {
124
5.43k
    Result.MemUsed = getMemUsage();
125
5.43k
    sys::Process::GetTimeUsage(now, user, sys);
126
5.43k
  } else {
127
5.38k
    sys::Process::GetTimeUsage(now, user, sys);
128
5.38k
    Result.MemUsed = getMemUsage();
129
5.38k
  }
130
10.8k
131
10.8k
  Result.WallTime = Seconds(now.time_since_epoch()).count();
132
10.8k
  Result.UserTime = Seconds(user).count();
133
10.8k
  Result.SystemTime = Seconds(sys).count();
134
10.8k
  return Result;
135
10.8k
}
136
137
5.38k
void Timer::startTimer() {
138
5.38k
  assert(!Running && "Cannot start a running timer");
139
5.38k
  Running = Triggered = true;
140
5.38k
  Signposts->startTimerInterval(this);
141
5.38k
  StartTime = TimeRecord::getCurrentTime(true);
142
5.38k
}
143
144
5.38k
void Timer::stopTimer() {
145
5.38k
  assert(Running && "Cannot stop a paused timer");
146
5.38k
  Running = false;
147
5.38k
  Time += TimeRecord::getCurrentTime(false);
148
5.38k
  Time -= StartTime;
149
5.38k
  Signposts->endTimerInterval(this);
150
5.38k
}
151
152
775
void Timer::clear() {
153
775
  Running = Triggered = false;
154
775
  Time = StartTime = TimeRecord();
155
775
}
156
157
14.1k
static void printVal(double Val, double Total, raw_ostream &OS) {
158
14.1k
  if (Total < 1e-7)   // Avoid dividing by zero.
159
0
    OS << "        -----     ";
160
14.1k
  else
161
14.1k
    OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
162
14.1k
}
163
164
3.54k
void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
165
3.54k
  if (Total.getUserTime())
166
3.54k
    printVal(getUserTime(), Total.getUserTime(), OS);
167
3.54k
  if (Total.getSystemTime())
168
3.54k
    printVal(getSystemTime(), Total.getSystemTime(), OS);
169
3.54k
  if (Total.getProcessTime())
170
3.54k
    printVal(getProcessTime(), Total.getProcessTime(), OS);
171
3.54k
  printVal(getWallTime(), Total.getWallTime(), OS);
172
3.54k
173
3.54k
  OS << "  ";
174
3.54k
175
3.54k
  if (Total.getMemUsed())
176
0
    OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
177
3.54k
}
178
179
180
//===----------------------------------------------------------------------===//
181
//   NamedRegionTimer Implementation
182
//===----------------------------------------------------------------------===//
183
184
namespace {
185
186
typedef StringMap<Timer> Name2TimerMap;
187
188
class Name2PairMap {
189
  StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
190
public:
191
14
  ~Name2PairMap() {
192
14
    for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
193
23
         I = Map.begin(), E = Map.end(); I != E; 
++I9
)
194
9
      delete I->second.first;
195
14
  }
196
197
  Timer &get(StringRef Name, StringRef Description, StringRef GroupName,
198
9
             StringRef GroupDescription) {
199
9
    sys::SmartScopedLock<true> L(*TimerLock);
200
9
201
9
    std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
202
9
203
9
    if (!GroupEntry.first)
204
9
      GroupEntry.first = new TimerGroup(GroupName, GroupDescription);
205
9
206
9
    Timer &T = GroupEntry.second[Name];
207
9
    if (!T.isInitialized())
208
9
      T.init(Name, Description, *GroupEntry.first);
209
9
    return T;
210
9
  }
211
};
212
213
}
214
215
static ManagedStatic<Name2PairMap> NamedGroupedTimers;
216
217
NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
218
                                   StringRef GroupName,
219
                                   StringRef GroupDescription, bool Enabled)
220
  : TimeRegion(!Enabled ? nullptr
221
                 : &NamedGroupedTimers->get(Name, Description, GroupName,
222
28.1M
                                            GroupDescription)) {}
223
224
//===----------------------------------------------------------------------===//
225
//   TimerGroup Implementation
226
//===----------------------------------------------------------------------===//
227
228
/// This is the global list of TimerGroups, maintained by the TimerGroup
229
/// ctor/dtor and is protected by the TimerLock lock.
230
static TimerGroup *TimerGroupList = nullptr;
231
232
TimerGroup::TimerGroup(StringRef Name, StringRef Description)
233
  : Name(Name.begin(), Name.end()),
234
23.0k
    Description(Description.begin(), Description.end()) {
235
23.0k
  // Add the group to TimerGroupList.
236
23.0k
  sys::SmartScopedLock<true> L(*TimerLock);
237
23.0k
  if (TimerGroupList)
238
53
    TimerGroupList->Prev = &Next;
239
23.0k
  Next = TimerGroupList;
240
23.0k
  Prev = &TimerGroupList;
241
23.0k
  TimerGroupList = this;
242
23.0k
}
243
244
TimerGroup::TimerGroup(StringRef Name, StringRef Description,
245
                       const StringMap<TimeRecord> &Records)
246
0
    : TimerGroup(Name, Description) {
247
0
  TimersToPrint.reserve(Records.size());
248
0
  for (const auto &P : Records)
249
0
    TimersToPrint.emplace_back(P.getValue(), P.getKey(), P.getKey());
250
0
  assert(TimersToPrint.size() == Records.size() && "Size mismatch");
251
0
}
Unexecuted instantiation: llvm::TimerGroup::TimerGroup(llvm::StringRef, llvm::StringRef, llvm::StringMap<llvm::TimeRecord, llvm::MallocAllocator> const&)
Unexecuted instantiation: llvm::TimerGroup::TimerGroup(llvm::StringRef, llvm::StringRef, llvm::StringMap<llvm::TimeRecord, llvm::MallocAllocator> const&)
252
253
23.0k
TimerGroup::~TimerGroup() {
254
23.0k
  // If the timer group is destroyed before the timers it owns, accumulate and
255
23.0k
  // print the timing data.
256
23.0k
  while (FirstTimer)
257
9
    removeTimer(*FirstTimer);
258
23.0k
259
23.0k
  // Remove the group from the TimerGroupList.
260
23.0k
  sys::SmartScopedLock<true> L(*TimerLock);
261
23.0k
  *Prev = Next;
262
23.0k
  if (Next)
263
32
    Next->Prev = Prev;
264
23.0k
}
265
266
267
41.4k
void TimerGroup::removeTimer(Timer &T) {
268
41.4k
  sys::SmartScopedLock<true> L(*TimerLock);
269
41.4k
270
41.4k
  // If the timer was started, move its data to TimersToPrint.
271
41.4k
  if (T.hasTriggered())
272
1.63k
    TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
273
41.4k
274
41.4k
  T.TG = nullptr;
275
41.4k
276
41.4k
  // Unlink the timer from our list.
277
41.4k
  *T.Prev = T.Next;
278
41.4k
  if (T.Next)
279
19.6k
    T.Next->Prev = T.Prev;
280
41.4k
281
41.4k
  // Print the report when all timers in this group are destroyed if some of
282
41.4k
  // them were started.
283
41.4k
  if (FirstTimer || 
TimersToPrint.empty()21.7k
)
284
41.3k
    return;
285
48
286
48
  std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
287
48
  PrintQueuedTimers(*OutStream);
288
48
}
289
290
41.4k
void TimerGroup::addTimer(Timer &T) {
291
41.4k
  sys::SmartScopedLock<true> L(*TimerLock);
292
41.4k
293
41.4k
  // Add the timer to our list.
294
41.4k
  if (FirstTimer)
295
19.6k
    FirstTimer->Prev = &T.Next;
296
41.4k
  T.Next = FirstTimer;
297
41.4k
  T.Prev = &FirstTimer;
298
41.4k
  FirstTimer = &T;
299
41.4k
}
300
301
77
void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
302
77
  // Sort the timers in descending order by amount of time taken.
303
77
  llvm::sort(TimersToPrint);
304
77
305
77
  TimeRecord Total;
306
77
  for (const PrintRecord &Record : TimersToPrint)
307
3.44k
    Total += Record.Time;
308
77
309
77
  // Print out timing header.
310
77
  OS << "===" << std::string(73, '-') << "===\n";
311
77
  // Figure out how many spaces to indent TimerGroup name.
312
77
  unsigned Padding = (80-Description.length())/2;
313
77
  if (Padding > 80) 
Padding = 00
; // Don't allow "negative" numbers
314
77
  OS.indent(Padding) << Description << '\n';
315
77
  OS << "===" << std::string(73, '-') << "===\n";
316
77
317
77
  // If this is not an collection of ungrouped times, print the total time.
318
77
  // Ungrouped timers don't really make sense to add up.  We still print the
319
77
  // TOTAL line to make the percentages make sense.
320
77
  if (this != getDefaultTimerGroup())
321
66
    OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
322
66
                 Total.getProcessTime(), Total.getWallTime());
323
77
  OS << '\n';
324
77
325
77
  if (Total.getUserTime())
326
77
    OS << "   ---User Time---";
327
77
  if (Total.getSystemTime())
328
77
    OS << "   --System Time--";
329
77
  if (Total.getProcessTime())
330
77
    OS << "   --User+System--";
331
77
  OS << "   ---Wall Time---";
332
77
  if (Total.getMemUsed())
333
0
    OS << "  ---Mem---";
334
77
  OS << "  --- Name ---\n";
335
77
336
77
  // Loop through all of the timing data, printing it out.
337
77
  for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
338
3.44k
                                              TimersToPrint.rend())) {
339
3.44k
    Record.Time.print(Total, OS);
340
3.44k
    OS << Record.Description << '\n';
341
3.44k
  }
342
77
343
77
  Total.print(Total, OS);
344
77
  OS << "Total\n\n";
345
77
  OS.flush();
346
77
347
77
  TimersToPrint.clear();
348
77
}
349
350
21.7k
void TimerGroup::prepareToPrintList(bool ResetTime) {
351
21.7k
  // See if any of our timers were started, if so add them to TimersToPrint.
352
23.5k
  for (Timer *T = FirstTimer; T; 
T = T->Next1.82k
) {
353
1.82k
    if (!T->hasTriggered()) 
continue8
;
354
1.81k
    bool WasRunning = T->isRunning();
355
1.81k
    if (WasRunning)
356
0
      T->stopTimer();
357
1.81k
358
1.81k
    TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
359
1.81k
360
1.81k
    if (ResetTime)
361
774
      T->clear();
362
1.81k
363
1.81k
    if (WasRunning)
364
0
      T->startTimer();
365
1.81k
  }
366
21.7k
}
367
368
21.7k
void TimerGroup::print(raw_ostream &OS, bool ResetAfterPrint) {
369
21.7k
  {
370
21.7k
    // After preparing the timers we can free the lock
371
21.7k
    sys::SmartScopedLock<true> L(*TimerLock);
372
21.7k
    prepareToPrintList(ResetAfterPrint);
373
21.7k
  }
374
21.7k
375
21.7k
  // If any timers were started, print the group.
376
21.7k
  if (!TimersToPrint.empty())
377
29
    PrintQueuedTimers(OS);
378
21.7k
}
379
380
0
void TimerGroup::clear() {
381
0
  sys::SmartScopedLock<true> L(*TimerLock);
382
0
  for (Timer *T = FirstTimer; T; T = T->Next)
383
0
    T->clear();
384
0
}
385
386
60.0k
void TimerGroup::printAll(raw_ostream &OS) {
387
60.0k
  sys::SmartScopedLock<true> L(*TimerLock);
388
60.0k
389
81.7k
  for (TimerGroup *TG = TimerGroupList; TG; 
TG = TG->Next21.7k
)
390
21.7k
    TG->print(OS);
391
60.0k
}
392
393
0
void TimerGroup::clearAll() {
394
0
  sys::SmartScopedLock<true> L(*TimerLock);
395
0
  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
396
0
    TG->clear();
397
0
}
398
399
void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
400
0
                                const char *suffix, double Value) {
401
0
  assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
402
0
         "TimerGroup name should not need quotes");
403
0
  assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
404
0
         "Timer name should not need quotes");
405
0
  constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
406
0
  OS << "\t\"time." << Name << '.' << R.Name << suffix
407
0
     << "\": " << format("%.*e", max_digits10 - 1, Value);
408
0
}
409
410
1
const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
411
1
  sys::SmartScopedLock<true> L(*TimerLock);
412
1
413
1
  prepareToPrintList(false);
414
1
  for (const PrintRecord &R : TimersToPrint) {
415
0
    OS << delim;
416
0
    delim = ",\n";
417
0
418
0
    const TimeRecord &T = R.Time;
419
0
    printJSONValue(OS, R, ".wall", T.getWallTime());
420
0
    OS << delim;
421
0
    printJSONValue(OS, R, ".user", T.getUserTime());
422
0
    OS << delim;
423
0
    printJSONValue(OS, R, ".sys", T.getSystemTime());
424
0
    if (T.getMemUsed()) {
425
0
      OS << delim;
426
0
      printJSONValue(OS, R, ".mem", T.getMemUsed());
427
0
    }
428
0
  }
429
1
  TimersToPrint.clear();
430
1
  return delim;
431
1
}
432
433
1
const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
434
1
  sys::SmartScopedLock<true> L(*TimerLock);
435
2
  for (TimerGroup *TG = TimerGroupList; TG; 
TG = TG->Next1
)
436
1
    delim = TG->printJSONValues(OS, delim);
437
1
  return delim;
438
1
}
439
440
6
void TimerGroup::ConstructTimerLists() {
441
6
  (void)*NamedGroupedTimers;
442
6
}