LLVM 17.0.0git
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
15#include "llvm/ADT/StringMap.h"
16#include "llvm/Support/JSON.h"
17#include "llvm/Support/Path.h"
20#include <algorithm>
21#include <cassert>
22#include <chrono>
23#include <mutex>
24#include <string>
25#include <vector>
26
27using namespace llvm;
28
29namespace {
30
31using std::chrono::duration;
32using std::chrono::duration_cast;
33using std::chrono::microseconds;
34using std::chrono::steady_clock;
35using std::chrono::system_clock;
36using std::chrono::time_point;
37using std::chrono::time_point_cast;
38
39struct TimeTraceProfilerInstances {
40 std::mutex Lock;
41 std::vector<TimeTraceProfiler *> List;
42};
43
44TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
45 static TimeTraceProfilerInstances Instances;
46 return Instances;
47}
48
49} // anonymous namespace
50
51// Per Thread instance
53
56}
57
58namespace {
59
60using ClockType = steady_clock;
61using TimePointType = time_point<ClockType>;
62using DurationType = duration<ClockType::rep, ClockType::period>;
63using CountAndDurationType = std::pair<size_t, DurationType>;
64using NameAndCountAndDurationType =
65 std::pair<std::string, CountAndDurationType>;
66
67/// Represents an open or completed time section entry to be captured.
68struct TimeTraceProfilerEntry {
69 const TimePointType Start;
70 TimePointType End;
71 const std::string Name;
72 const std::string Detail;
73
74 TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
75 std::string &&Dt)
76 : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
77 Detail(std::move(Dt)) {}
78
79 // Calculate timings for FlameGraph. Cast time points to microsecond precision
80 // rather than casting duration. This avoids truncation issues causing inner
81 // scopes overruning outer scopes.
82 ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
83 return (time_point_cast<microseconds>(Start) -
84 time_point_cast<microseconds>(StartTime))
85 .count();
86 }
87
88 ClockType::rep getFlameGraphDurUs() const {
89 return (time_point_cast<microseconds>(End) -
90 time_point_cast<microseconds>(Start))
91 .count();
92 }
93};
94
95} // anonymous namespace
96
99 : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
100 ProcName(ProcName), Pid(sys::Process::getProcessId()),
103 }
104
105 void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
106 Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name),
107 Detail());
108 }
109
110 void end() {
111 assert(!Stack.empty() && "Must call begin() first");
112 TimeTraceProfilerEntry &E = Stack.back();
113 E.End = ClockType::now();
114
115 // Check that end times monotonically increase.
116 assert((Entries.empty() ||
117 (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
118 Entries.back().getFlameGraphStartUs(StartTime) +
119 Entries.back().getFlameGraphDurUs())) &&
120 "TimeProfiler scope ended earlier than previous scope");
121
122 // Calculate duration at full precision for overall counts.
123 DurationType Duration = E.End - E.Start;
124
125 // Only include sections longer or equal to TimeTraceGranularity msec.
126 if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
128
129 // Track total time taken by each "name", but only the topmost levels of
130 // them; e.g. if there's a template instantiation that instantiates other
131 // templates from within, we only want to add the topmost one. "topmost"
132 // happens to be the ones that don't have any currently open entries above
133 // itself.
135 [&](const TimeTraceProfilerEntry &Val) {
136 return Val.Name == E.Name;
137 })) {
138 auto &CountAndTotal = CountAndTotalPerName[E.Name];
139 CountAndTotal.first++;
140 CountAndTotal.second += Duration;
141 }
142
143 Stack.pop_back();
144 }
145
146 // Write events from this TimeTraceProfilerInstance and
147 // ThreadTimeTraceProfilerInstances.
149 // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
150 auto &Instances = getTimeTraceProfilerInstances();
151 std::lock_guard<std::mutex> Lock(Instances.Lock);
152 assert(Stack.empty() &&
153 "All profiler sections should be ended when calling write");
154 assert(llvm::all_of(Instances.List,
155 [](const auto &TTP) { return TTP->Stack.empty(); }) &&
156 "All profiler sections should be ended when calling write");
157
158 json::OStream J(OS);
159 J.objectBegin();
160 J.attributeBegin("traceEvents");
161 J.arrayBegin();
162
163 // Emit all events for the main flame graph.
164 auto writeEvent = [&](const auto &E, uint64_t Tid) {
165 auto StartUs = E.getFlameGraphStartUs(StartTime);
166 auto DurUs = E.getFlameGraphDurUs();
167
168 J.object([&] {
169 J.attribute("pid", Pid);
170 J.attribute("tid", int64_t(Tid));
171 J.attribute("ph", "X");
172 J.attribute("ts", StartUs);
173 J.attribute("dur", DurUs);
174 J.attribute("name", E.Name);
175 if (!E.Detail.empty()) {
176 J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
177 }
178 });
179 };
180 for (const TimeTraceProfilerEntry &E : Entries)
181 writeEvent(E, this->Tid);
182 for (const TimeTraceProfiler *TTP : Instances.List)
183 for (const TimeTraceProfilerEntry &E : TTP->Entries)
184 writeEvent(E, TTP->Tid);
185
186 // Emit totals by section name as additional "thread" events, sorted from
187 // longest one.
188 // Find highest used thread id.
189 uint64_t MaxTid = this->Tid;
190 for (const TimeTraceProfiler *TTP : Instances.List)
191 MaxTid = std::max(MaxTid, TTP->Tid);
192
193 // Combine all CountAndTotalPerName from threads into one.
194 StringMap<CountAndDurationType> AllCountAndTotalPerName;
195 auto combineStat = [&](const auto &Stat) {
196 StringRef Key = Stat.getKey();
197 auto Value = Stat.getValue();
198 auto &CountAndTotal = AllCountAndTotalPerName[Key];
199 CountAndTotal.first += Value.first;
200 CountAndTotal.second += Value.second;
201 };
202 for (const auto &Stat : CountAndTotalPerName)
203 combineStat(Stat);
204 for (const TimeTraceProfiler *TTP : Instances.List)
205 for (const auto &Stat : TTP->CountAndTotalPerName)
206 combineStat(Stat);
207
208 std::vector<NameAndCountAndDurationType> SortedTotals;
209 SortedTotals.reserve(AllCountAndTotalPerName.size());
210 for (const auto &Total : AllCountAndTotalPerName)
211 SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue());
212
213 llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A,
214 const NameAndCountAndDurationType &B) {
215 return A.second.second > B.second.second;
216 });
217
218 // Report totals on separate threads of tracing file.
219 uint64_t TotalTid = MaxTid + 1;
220 for (const NameAndCountAndDurationType &Total : SortedTotals) {
221 auto DurUs = duration_cast<microseconds>(Total.second.second).count();
222 auto Count = AllCountAndTotalPerName[Total.first].first;
223
224 J.object([&] {
225 J.attribute("pid", Pid);
226 J.attribute("tid", int64_t(TotalTid));
227 J.attribute("ph", "X");
228 J.attribute("ts", 0);
229 J.attribute("dur", DurUs);
230 J.attribute("name", "Total " + Total.first);
231 J.attributeObject("args", [&] {
232 J.attribute("count", int64_t(Count));
233 J.attribute("avg ms", int64_t(DurUs / Count / 1000));
234 });
235 });
236
237 ++TotalTid;
238 }
239
240 auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
241 StringRef arg) {
242 J.object([&] {
243 J.attribute("cat", "");
244 J.attribute("pid", Pid);
245 J.attribute("tid", int64_t(Tid));
246 J.attribute("ts", 0);
247 J.attribute("ph", "M");
248 J.attribute("name", Name);
249 J.attributeObject("args", [&] { J.attribute("name", arg); });
250 });
251 };
252
253 writeMetadataEvent("process_name", Tid, ProcName);
254 writeMetadataEvent("thread_name", Tid, ThreadName);
255 for (const TimeTraceProfiler *TTP : Instances.List)
256 writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
257
258 J.arrayEnd();
259 J.attributeEnd();
260
261 // Emit the absolute time when this TimeProfiler started.
262 // This can be used to combine the profiling data from
263 // multiple processes and preserve actual time intervals.
264 J.attribute("beginningOfTime",
265 time_point_cast<microseconds>(BeginningOfTime)
266 .time_since_epoch()
267 .count());
268
269 J.objectEnd();
270 }
271
275 // System clock time when the session was begun.
276 const time_point<system_clock> BeginningOfTime;
277 // Profiling clock time when the session was begun.
278 const TimePointType StartTime;
279 const std::string ProcName;
283
284 // Minimum time granularity (in microseconds)
285 const unsigned TimeTraceGranularity;
286};
287
288void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
289 StringRef ProcName) {
291 "Profiler should not be initialized");
293 TimeTraceGranularity, llvm::sys::path::filename(ProcName));
294}
295
296// Removes all TimeTraceProfilerInstances.
297// Called from main thread.
301
302 auto &Instances = getTimeTraceProfilerInstances();
303 std::lock_guard<std::mutex> Lock(Instances.Lock);
304 for (auto *TTP : Instances.List)
305 delete TTP;
306 Instances.List.clear();
307}
308
309// Finish TimeTraceProfilerInstance on a worker thread.
310// This doesn't remove the instance, just moves the pointer to global vector.
312 auto &Instances = getTimeTraceProfilerInstances();
313 std::lock_guard<std::mutex> Lock(Instances.Lock);
314 Instances.List.push_back(TimeTraceProfilerInstance);
316}
317
320 "Profiler object can't be null");
322}
323
325 StringRef FallbackFileName) {
327 "Profiler object can't be null");
328
329 std::string Path = PreferredFileName.str();
330 if (Path.empty()) {
331 Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
332 Path += ".time-trace";
333 }
334
335 std::error_code EC;
337 if (EC)
338 return createStringError(EC, "Could not open " + Path);
339
341 return Error::success();
342}
343
345 if (TimeTraceProfilerInstance != nullptr)
347 [&]() { return std::string(Detail); });
348}
349
351 llvm::function_ref<std::string()> Detail) {
352 if (TimeTraceProfilerInstance != nullptr)
353 TimeTraceProfilerInstance->begin(std::string(Name), Detail);
354}
355
357 if (TimeTraceProfilerInstance != nullptr)
359}
This file defines the StringMap class.
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
static GCRegistry::Add< OcamlGC > B("ocaml", "ocaml 3.10-compatible GC")
static GCRegistry::Add< ErlangGC > A("erlang", "erlang-compatible garbage collector")
static GCRegistry::Add< CoreCLRGC > E("coreclr", "CoreCLR-compatible GC")
#define LLVM_THREAD_LOCAL
\macro LLVM_THREAD_LOCAL A thread-local storage specifier which can be used with globals,...
Definition: Compiler.h:532
std::string Name
This file supports working with JSON data.
Provides a library for accessing information about this process and other processes on the operating ...
const NodeList & List
Definition: RDFGraph.cpp:199
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
raw_pwrite_stream & OS
static LLVM_THREAD_LOCAL TimeTraceProfiler * TimeTraceProfilerInstance
Lightweight error class with error context and mandatory checking.
Definition: Error.h:156
static ErrorSuccess success()
Create a success value.
Definition: Error.h:330
SmallString - A SmallString is just a SmallVector with methods and accessors that make it work better...
Definition: SmallString.h:26
bool empty() const
Definition: SmallVector.h:94
reference emplace_back(ArgTypes &&... Args)
Definition: SmallVector.h:941
This is a 'vector' (really, a variable-sized array), optimized for the case when the array is small.
Definition: SmallVector.h:1200
unsigned size() const
Definition: StringMap.h:95
StringMap - This is an unconventional map that is specialized for handling keys that are "strings",...
Definition: StringMap.h:111
StringRef - Represent a constant reference to a string, i.e.
Definition: StringRef.h:50
std::string str() const
str - Get the contents as an std::string.
Definition: StringRef.h:222
LLVM Value Representation.
Definition: Value.h:74
An efficient, type-erasing, non-owning reference to a callable.
json::OStream allows writing well-formed JSON without materializing all structures as json::Value ahe...
Definition: JSON.h:956
void object(Block Contents)
Emit an object whose elements are emitted in the provided Block.
Definition: JSON.h:986
void attributeObject(llvm::StringRef Key, Block Contents)
Emit an attribute whose value is an object with attributes from the Block.
Definition: JSON.h:1019
void attributeBegin(llvm::StringRef Key)
Definition: JSON.cpp:880
void attribute(llvm::StringRef Key, const Value &Contents)
Emit an attribute whose value is self-contained (number, vector<int> etc).
Definition: JSON.h:1011
void arrayBegin()
Definition: JSON.cpp:842
void objectBegin()
Definition: JSON.cpp:861
void attributeEnd()
Definition: JSON.cpp:900
void objectEnd()
Definition: JSON.cpp:869
A raw_ostream that writes to a file descriptor.
Definition: raw_ostream.h:454
An abstract base class for streams implementations that also support a pwrite operation.
Definition: raw_ostream.h:428
A collection of legacy interfaces for querying information about the current executing process.
Definition: Process.h:43
@ OF_TextWithCRLF
The file should be opened in text mode and use a carriage linefeed '\r '.
Definition: FileSystem.h:770
StringRef filename(StringRef path, Style style=Style::native)
Get filename.
Definition: Path.cpp:577
This is an optimization pass for GlobalISel generic memory operations.
Definition: AddressRanges.h:18
auto drop_begin(T &&RangeOrContainer, size_t N=1)
Return a range covering RangeOrContainer with the first N elements excluded.
Definition: STLExtras.h:397
bool all_of(R &&range, UnaryPredicate P)
Provide wrappers to std::all_of which take ranges instead of having to pass begin/end explicitly.
Definition: STLExtras.h:1782
void timeTraceProfilerInitialize(unsigned TimeTraceGranularity, StringRef ProcName)
Initialize the time trace profiler.
Error createStringError(std::error_code EC, char const *Fmt, const Ts &... Vals)
Create formatted StringError object.
Definition: Error.h:1246
TimeTraceProfiler * getTimeTraceProfilerInstance()
auto reverse(ContainerTy &&C)
Definition: STLExtras.h:495
void timeTraceProfilerFinishThread()
Finish a time trace profiler running on a worker thread.
void timeTraceProfilerBegin(StringRef Name, StringRef Detail)
Manually begin a time section, with the given Name and Detail.
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1730
bool none_of(R &&Range, UnaryPredicate P)
Provide wrappers to std::none_of which take ranges instead of having to pass begin/end explicitly.
Definition: STLExtras.h:1796
void timeTraceProfilerEnd()
Manually end the last time section.
void get_thread_name(SmallVectorImpl< char > &Name)
Get the name of the current thread.
Definition: Threading.cpp:39
uint64_t get_threadid()
Return the current thread id, as used in various OS system calls.
Definition: Threading.cpp:33
auto count(R &&Range, const E &Element)
Wrapper function around std::count to count the number of times an element Element occurs in the give...
Definition: STLExtras.h:1974
OutputIt move(R &&Range, OutputIt Out)
Provide wrappers to std::move which take ranges instead of having to pass begin/end explicitly.
Definition: STLExtras.h:1909
void timeTraceProfilerCleanup()
Cleanup the time trace profiler, if it was initialized.
void timeTraceProfilerWrite(raw_pwrite_stream &OS)
Write profiling data to output stream.
Definition: BitVector.h:851
#define N
SmallVector< TimeTraceProfilerEntry, 16 > Stack
const sys::Process::Pid Pid
void write(raw_pwrite_stream &OS)
StringMap< CountAndDurationType > CountAndTotalPerName
const unsigned TimeTraceGranularity
TimeTraceProfiler(unsigned TimeTraceGranularity=0, StringRef ProcName="")
const time_point< system_clock > BeginningOfTime
SmallString< 0 > ThreadName
const std::string ProcName
SmallVector< TimeTraceProfilerEntry, 128 > Entries
const TimePointType StartTime
void begin(std::string Name, llvm::function_ref< std::string()> Detail)