LLVM  16.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"
18 #include "llvm/Support/Process.h"
19 #include "llvm/Support/Threading.h"
20 #include <algorithm>
21 #include <cassert>
22 #include <chrono>
23 #include <mutex>
24 #include <string>
25 #include <vector>
26 
27 using namespace llvm;
28 
29 namespace {
30 
31 using std::chrono::duration;
32 using std::chrono::duration_cast;
33 using std::chrono::microseconds;
34 using std::chrono::steady_clock;
35 using std::chrono::system_clock;
36 using std::chrono::time_point;
37 using std::chrono::time_point_cast;
38 
39 struct TimeTraceProfilerInstances {
40  std::mutex Lock;
41  std::vector<TimeTraceProfiler *> List;
42 };
43 
44 TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
45  static TimeTraceProfilerInstances Instances;
46  return Instances;
47 }
48 
49 } // anonymous namespace
50 
51 // Per Thread instance
53 
56 }
57 
58 namespace {
59 
60 using ClockType = steady_clock;
61 using TimePointType = time_point<ClockType>;
62 using DurationType = duration<ClockType::rep, ClockType::period>;
63 using CountAndDurationType = std::pair<size_t, DurationType>;
64 using NameAndCountAndDurationType =
65  std::pair<std::string, CountAndDurationType>;
66 
67 /// Represents an open or completed time section entry to be captured.
68 struct 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;
282  const uint64_t Tid;
283 
284  // Minimum time granularity (in microseconds)
285  const unsigned TimeTraceGranularity;
286 };
287 
288 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
289  StringRef ProcName) {
290  assert(TimeTraceProfilerInstance == nullptr &&
291  "Profiler should not be initialized");
293  TimeTraceGranularity, llvm::sys::path::filename(ProcName));
294 }
295 
296 // Removes all TimeTraceProfilerInstances.
297 // Called from main thread.
300  TimeTraceProfilerInstance = nullptr;
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);
315  TimeTraceProfilerInstance = nullptr;
316 }
317 
319  assert(TimeTraceProfilerInstance != nullptr &&
320  "Profiler object can't be null");
322 }
323 
325  StringRef FallbackFileName) {
326  assert(TimeTraceProfilerInstance != nullptr &&
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)
346  TimeTraceProfilerInstance->begin(std::string(Name),
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 }
llvm::json::OStream::attributeBegin
void attributeBegin(llvm::StringRef Key)
Definition: JSON.cpp:879
llvm
This is an optimization pass for GlobalISel generic memory operations.
Definition: AddressRanges.h:18
llvm::none_of
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:1604
llvm::drop_begin
auto drop_begin(T &&RangeOrContainer, size_t N=1)
Return a range covering RangeOrContainer with the first N elements excluded.
Definition: STLExtras.h:268
llvm::getTimeTraceProfilerInstance
TimeTraceProfiler * getTimeTraceProfilerInstance()
Definition: TimeProfiler.cpp:54
llvm::timeTraceProfilerWrite
void timeTraceProfilerWrite(raw_pwrite_stream &OS)
Write profiling data to output stream.
Definition: TimeProfiler.cpp:318
llvm::TimeTraceProfiler::TimeTraceGranularity
const unsigned TimeTraceGranularity
Definition: TimeProfiler.cpp:285
llvm::json::OStream::attributeEnd
void attributeEnd()
Definition: JSON.cpp:899
llvm::TimeTraceProfiler::StartTime
const TimePointType StartTime
Definition: TimeProfiler.cpp:278
llvm::timeTraceProfilerCleanup
void timeTraceProfilerCleanup()
Cleanup the time trace profiler, if it was initialized.
Definition: TimeProfiler.cpp:298
llvm::SmallVector< TimeTraceProfilerEntry, 16 >
Path.h
llvm::TimeTraceProfiler::ThreadName
SmallString< 0 > ThreadName
Definition: TimeProfiler.cpp:281
llvm::Error::success
static ErrorSuccess success()
Create a success value.
Definition: Error.h:329
llvm::TimeTraceProfiler::CountAndTotalPerName
StringMap< CountAndDurationType > CountAndTotalPerName
Definition: TimeProfiler.cpp:274
llvm::TimeTraceProfiler::end
void end()
Definition: TimeProfiler.cpp:110
llvm::TimeTraceProfiler::Tid
const uint64_t Tid
Definition: TimeProfiler.cpp:282
llvm::TimeTraceProfiler::Stack
SmallVector< TimeTraceProfilerEntry, 16 > Stack
Definition: TimeProfiler.cpp:272
llvm::sys::Process::Pid
int32_t Pid
Definition: Process.h:45
llvm::max
Expected< ExpressionValue > max(const ExpressionValue &Lhs, const ExpressionValue &Rhs)
Definition: FileCheck.cpp:337
llvm::timeTraceProfilerFinishThread
void timeTraceProfilerFinishThread()
Finish a time trace profiler running on a worker thread.
Definition: TimeProfiler.cpp:311
llvm::timeTraceProfilerInitialize
void timeTraceProfilerInitialize(unsigned TimeTraceGranularity, StringRef ProcName)
Initialize the time trace profiler.
Definition: TimeProfiler.cpp:288
llvm::sys::Process
A collection of legacy interfaces for querying information about the current executing process.
Definition: Process.h:43
llvm::all_of
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:1590
Process.h
LLVM_THREAD_LOCAL
#define LLVM_THREAD_LOCAL
\macro LLVM_THREAD_LOCAL A thread-local storage specifier which can be used with globals,...
Definition: Compiler.h:527
E
static GCRegistry::Add< CoreCLRGC > E("coreclr", "CoreCLR-compatible GC")
llvm::json::OStream::object
void object(Block Contents)
Emit an object whose elements are emitted in the provided Block.
Definition: JSON.h:986
llvm::timeTraceProfilerBegin
void timeTraceProfilerBegin(StringRef Name, StringRef Detail)
Manually begin a time section, with the given Name and Detail.
Definition: TimeProfiler.cpp:344
llvm::get_threadid
uint64_t get_threadid()
Return the current thread id, as used in various OS system calls.
llvm::Duration
Definition: Duration.h:20
llvm::TimeTraceProfiler::ProcName
const std::string ProcName
Definition: TimeProfiler.cpp:279
llvm::AMDGPU::PALMD::Key
Key
PAL metadata keys.
Definition: AMDGPUMetadata.h:486
B
static GCRegistry::Add< OcamlGC > B("ocaml", "ocaml 3.10-compatible GC")
llvm::TimeTraceProfiler::Entries
SmallVector< TimeTraceProfilerEntry, 128 > Entries
Definition: TimeProfiler.cpp:273
llvm::get_thread_name
void get_thread_name(SmallVectorImpl< char > &Name)
Get the name of the current thread.
STLFunctionalExtras.h
JSON.h
llvm::json::OStream::objectEnd
void objectEnd()
Definition: JSON.cpp:868
now
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
Definition: ArchiveWriter.cpp:327
llvm::StringMap< CountAndDurationType >
llvm::SmallString< 0 >
llvm::sys::fs::OF_TextWithCRLF
@ OF_TextWithCRLF
The file should be opened in text mode and use a carriage linefeed '\r '.
Definition: FileSystem.h:770
llvm::sort
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1538
llvm::function_ref
An efficient, type-erasing, non-owning reference to a callable.
Definition: STLFunctionalExtras.h:36
llvm::TimeTraceProfiler
Definition: TimeProfiler.cpp:97
llvm::TimeTraceProfiler::begin
void begin(std::string Name, llvm::function_ref< std::string()> Detail)
Definition: TimeProfiler.cpp:105
Threading.h
llvm::json::OStream
json::OStream allows writing well-formed JSON without materializing all structures as json::Value ahe...
Definition: JSON.h:956
llvm::count
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:1700
uint64_t
llvm::raw_pwrite_stream
An abstract base class for streams implementations that also support a pwrite operation.
Definition: raw_ostream.h:414
llvm::TimeTraceProfiler::BeginningOfTime
const time_point< system_clock > BeginningOfTime
Definition: TimeProfiler.cpp:276
llvm::TimeTraceProfiler::write
void write(raw_pwrite_stream &OS)
Definition: TimeProfiler.cpp:148
move
compiles ldr LCPI1_0 ldr ldr mov lsr tst moveq r1 ldr LCPI1_1 and r0 bx lr It would be better to do something like to fold the shift into the conditional move
Definition: README.txt:546
llvm::json::OStream::arrayBegin
void arrayBegin()
Definition: JSON.cpp:841
assert
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
llvm::move
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:1666
llvm::StringMapImpl::size
unsigned size() const
Definition: StringMap.h:95
llvm::StringRef
StringRef - Represent a constant reference to a string, i.e.
Definition: StringRef.h:50
S
add sub stmia L5 ldr r0 bl L_printf $stub Instead of a and a wouldn t it be better to do three moves *Return an aggregate type is even return S
Definition: README.txt:210
llvm::raw_fd_ostream
A raw_ostream that writes to a file descriptor.
Definition: raw_ostream.h:440
llvm::TimeTraceProfiler::TimeTraceProfiler
TimeTraceProfiler(unsigned TimeTraceGranularity=0, StringRef ProcName="")
Definition: TimeProfiler.cpp:98
llvm::createStringError
Error createStringError(std::error_code EC, char const *Fmt, const Ts &... Vals)
Create formatted StringError object.
Definition: Error.h:1239
llvm::GraphProgram::Name
Name
Definition: GraphWriter.h:50
std
Definition: BitVector.h:851
llvm::Error
Lightweight error class with error context and mandatory checking.
Definition: Error.h:155
llvm::sys::path::filename
StringRef filename(StringRef path, Style style=Style::native)
Get filename.
Definition: Path.cpp:577
List
const NodeList & List
Definition: RDFGraph.cpp:199
N
#define N
llvm::json::OStream::arrayEnd
void arrayEnd()
Definition: JSON.cpp:849
TimeTraceProfilerInstance
static LLVM_THREAD_LOCAL TimeTraceProfiler * TimeTraceProfilerInstance
Definition: TimeProfiler.cpp:52
llvm::reverse
auto reverse(ContainerTy &&C)
Definition: STLExtras.h:365
llvm::json::OStream::attributeObject
void attributeObject(llvm::StringRef Key, Block Contents)
Emit an attribute whose value is an object with attributes from the Block.
Definition: JSON.h:1019
llvm::timeTraceProfilerEnd
void timeTraceProfilerEnd()
Manually end the last time section.
Definition: TimeProfiler.cpp:356
llvm::StringRef::str
std::string str() const
str - Get the contents as an std::string.
Definition: StringRef.h:221
StringMap.h
llvm::json::OStream::attribute
void attribute(llvm::StringRef Key, const Value &Contents)
Emit an attribute whose value is self-contained (number, vector<int> etc).
Definition: JSON.h:1011
llvm::TimeTraceProfiler::Pid
const sys::Process::Pid Pid
Definition: TimeProfiler.cpp:280
llvm::json::OStream::objectBegin
void objectBegin()
Definition: JSON.cpp:860
llvm::Value
LLVM Value Representation.
Definition: Value.h:74
TimeProfiler.h
llvm::SmallVectorImpl::emplace_back
reference emplace_back(ArgTypes &&... Args)
Definition: SmallVector.h:923