LLVM  10.0.0svn
TimeProfiler.cpp
Go to the documentation of this file.
1 //===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
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 // This file implements hierarchical time profiler.
10 //
11 //===----------------------------------------------------------------------===//
12 
14 #include "llvm/ADT/StringMap.h"
17 #include "llvm/Support/JSON.h"
18 #include <cassert>
19 #include <chrono>
20 #include <string>
21 #include <vector>
22 
23 using namespace std::chrono;
24 
25 namespace llvm {
26 
28 
29 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
30 typedef time_point<steady_clock> TimePointType;
31 typedef std::pair<size_t, DurationType> CountAndDurationType;
32 typedef std::pair<std::string, CountAndDurationType>
34 
35 struct Entry {
36  TimePointType Start;
37  TimePointType End;
38  std::string Name;
39  std::string Detail;
40 
41  Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
42  : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
43  Detail(std::move(Dt)){};
44 
45  // Calculate timings for FlameGraph. Cast time points to microsecond precision
46  // rather than casting duration. This avoid truncation issues causing inner
47  // scopes overruning outer scopes.
48  steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
49  return (time_point_cast<microseconds>(Start) -
50  time_point_cast<microseconds>(StartTime))
51  .count();
52  }
53 
54  steady_clock::rep getFlameGraphDurUs() const {
55  return (time_point_cast<microseconds>(End) -
56  time_point_cast<microseconds>(Start))
57  .count();
58  }
59 };
60 
63  StartTime = steady_clock::now();
64  }
65 
66  void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
67  Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
68  Detail());
69  }
70 
71  void end() {
72  assert(!Stack.empty() && "Must call begin() first");
73  auto &E = Stack.back();
74  E.End = steady_clock::now();
75 
76  // Check that end times monotonically increase.
77  assert((Entries.empty() ||
78  (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
79  Entries.back().getFlameGraphStartUs(StartTime) +
80  Entries.back().getFlameGraphDurUs())) &&
81  "TimeProfiler scope ended earlier than previous scope");
82 
83  // Calculate duration at full precision for overall counts.
84  DurationType Duration = E.End - E.Start;
85 
86  // Only include sections longer or equal to TimeTraceGranularity msec.
87  if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
88  Entries.emplace_back(E);
89 
90  // Track total time taken by each "name", but only the topmost levels of
91  // them; e.g. if there's a template instantiation that instantiates other
92  // templates from within, we only want to add the topmost one. "topmost"
93  // happens to be the ones that don't have any currently open entries above
94  // itself.
95  if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
96  return Val.Name == E.Name;
97  }) == Stack.rend()) {
98  auto &CountAndTotal = CountAndTotalPerName[E.Name];
99  CountAndTotal.first++;
100  CountAndTotal.second += Duration;
101  }
102 
103  Stack.pop_back();
104  }
105 
107  assert(Stack.empty() &&
108  "All profiler sections should be ended when calling Write");
109  json::OStream J(OS);
110  J.objectBegin();
111  J.attributeBegin("traceEvents");
112  J.arrayBegin();
113 
114  // Emit all events for the main flame graph.
115  for (const auto &E : Entries) {
116  auto StartUs = E.getFlameGraphStartUs(StartTime);
117  auto DurUs = E.getFlameGraphDurUs();
118 
119  J.object([&]{
120  J.attribute("pid", 1);
121  J.attribute("tid", 0);
122  J.attribute("ph", "X");
123  J.attribute("ts", StartUs);
124  J.attribute("dur", DurUs);
125  J.attribute("name", E.Name);
126  J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
127  });
128  }
129 
130  // Emit totals by section name as additional "thread" events, sorted from
131  // longest one.
132  int Tid = 1;
133  std::vector<NameAndCountAndDurationType> SortedTotals;
134  SortedTotals.reserve(CountAndTotalPerName.size());
135  for (const auto &E : CountAndTotalPerName)
136  SortedTotals.emplace_back(E.getKey(), E.getValue());
137 
138  llvm::sort(SortedTotals.begin(), SortedTotals.end(),
139  [](const NameAndCountAndDurationType &A,
141  return A.second.second > B.second.second;
142  });
143  for (const auto &E : SortedTotals) {
144  auto DurUs = duration_cast<microseconds>(E.second.second).count();
145  auto Count = CountAndTotalPerName[E.first].first;
146 
147  J.object([&]{
148  J.attribute("pid", 1);
149  J.attribute("tid", Tid);
150  J.attribute("ph", "X");
151  J.attribute("ts", 0);
152  J.attribute("dur", DurUs);
153  J.attribute("name", "Total " + E.first);
154  J.attributeObject("args", [&] {
155  J.attribute("count", int64_t(Count));
156  J.attribute("avg ms", int64_t(DurUs / Count / 1000));
157  });
158  });
159 
160  ++Tid;
161  }
162 
163  // Emit metadata event with process name.
164  J.object([&] {
165  J.attribute("cat", "");
166  J.attribute("pid", 1);
167  J.attribute("tid", 0);
168  J.attribute("ts", 0);
169  J.attribute("ph", "M");
170  J.attribute("name", "process_name");
171  J.attributeObject("args", [&] { J.attribute("name", "clang"); });
172  });
173 
174  J.arrayEnd();
175  J.attributeEnd();
176  J.objectEnd();
177  }
178 
182  TimePointType StartTime;
183 
184  // Minimum time granularity (in microseconds)
186 };
187 
188 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity) {
189  assert(TimeTraceProfilerInstance == nullptr &&
190  "Profiler should not be initialized");
191  TimeTraceProfilerInstance = new TimeTraceProfiler();
192  TimeTraceProfilerInstance->TimeTraceGranularity = TimeTraceGranularity;
193 }
194 
197  TimeTraceProfilerInstance = nullptr;
198 }
199 
201  assert(TimeTraceProfilerInstance != nullptr &&
202  "Profiler object can't be null");
203  TimeTraceProfilerInstance->Write(OS);
204 }
205 
207  if (TimeTraceProfilerInstance != nullptr)
208  TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
209 }
210 
212  llvm::function_ref<std::string()> Detail) {
213  if (TimeTraceProfilerInstance != nullptr)
214  TimeTraceProfilerInstance->begin(Name, Detail);
215 }
216 
218  if (TimeTraceProfilerInstance != nullptr)
219  TimeTraceProfilerInstance->end();
220 }
221 
222 } // namespace llvm
void Write(raw_pwrite_stream &OS)
This class represents lattice values for constants.
Definition: AllocatorList.h:23
amdgpu Simplify well known AMD library false FunctionCallee Value const Twine & Name
StringMap< CountAndDurationType > CountAndTotalPerName
std::pair< size_t, DurationType > CountAndDurationType
An efficient, type-erasing, non-owning reference to a callable.
Definition: STLExtras.h:104
void timeTraceProfilerEnd()
Manually end the last time section.
std::string Name
Definition: BitVector.h:937
json::OStream allows writing well-formed JSON without materializing all structures as json::Value ahe...
Definition: JSON.h:751
TimePointType Start
SmallVector< Entry, 16 > Stack
std::pair< std::string, CountAndDurationType > NameAndCountAndDurationType
auto count(R &&Range, const E &Element) -> typename std::iterator_traits< decltype(adl_begin(Range))>::difference_type
Wrapper function around std::count to count the number of times an element Element occurs in the give...
Definition: STLExtras.h:1231
std::string Detail
void begin(std::string Name, llvm::function_ref< std::string()> Detail)
void timeTraceProfilerCleanup()
Cleanup the time trace profiler, if it was initialized.
duration< steady_clock::rep, steady_clock::period > DurationType
static GCRegistry::Add< OcamlGC > B("ocaml", "ocaml 3.10-compatible GC")
Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
void timeTraceProfilerBegin(StringRef Name, StringRef Detail)
Manually begin a time section, with the given Name and Detail.
static GCRegistry::Add< CoreCLRGC > E("coreclr", "CoreCLR-compatible GC")
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const
auto find_if(R &&Range, UnaryPredicate P) -> decltype(adl_begin(Range))
Provide wrappers to std::find_if which take ranges instead of having to pass begin/end explicitly...
Definition: STLExtras.h:1193
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1095
This is a &#39;vector&#39; (really, a variable-sized array), optimized for the case when the array is small...
Definition: SmallVector.h:837
TimePointType End
void timeTraceProfilerWrite(raw_pwrite_stream &OS)
Write profiling data to output file.
TimeTraceProfiler * TimeTraceProfilerInstance
#define N
SmallVector< Entry, 128 > Entries
This file supports working with JSON data.
void timeTraceProfilerInitialize(unsigned TimeTraceGranularity)
Initialize the time trace profiler.
An abstract base class for streams implementations that also support a pwrite operation.
Definition: raw_ostream.h:359
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
StringRef - Represent a constant reference to a string, i.e.
Definition: StringRef.h:48
steady_clock::rep getFlameGraphDurUs() const
time_point< steady_clock > TimePointType