LLVM  14.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"
18 #include "llvm/Support/Path.h"
19 #include "llvm/Support/Process.h"
20 #include "llvm/Support/Threading.h"
21 #include <algorithm>
22 #include <cassert>
23 #include <chrono>
24 #include <mutex>
25 #include <string>
26 #include <vector>
27 
28 using namespace std::chrono;
29 using namespace llvm;
30 
31 static std::mutex Mu;
32 // List of all instances
35 // Per Thread instance
37 
40 }
41 
42 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
43 typedef time_point<steady_clock> TimePointType;
44 typedef std::pair<size_t, DurationType> CountAndDurationType;
45 typedef std::pair<std::string, CountAndDurationType>
47 
48 namespace {
49 struct Entry {
50  const TimePointType Start;
51  TimePointType End;
52  const std::string Name;
53  const std::string Detail;
54 
55  Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
56  : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
57  Detail(std::move(Dt)) {}
58 
59  // Calculate timings for FlameGraph. Cast time points to microsecond precision
60  // rather than casting duration. This avoid truncation issues causing inner
61  // scopes overruning outer scopes.
62  steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
63  return (time_point_cast<microseconds>(Start) -
64  time_point_cast<microseconds>(StartTime))
65  .count();
66  }
67 
68  steady_clock::rep getFlameGraphDurUs() const {
69  return (time_point_cast<microseconds>(End) -
70  time_point_cast<microseconds>(Start))
71  .count();
72  }
73 };
74 } // namespace
75 
77  TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
78  : BeginningOfTime(system_clock::now()), StartTime(steady_clock::now()),
79  ProcName(ProcName), Pid(sys::Process::getProcessId()),
80  Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {
81  llvm::get_thread_name(ThreadName);
82  }
83 
84  void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
85  Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
86  Detail());
87  }
88 
89  void end() {
90  assert(!Stack.empty() && "Must call begin() first");
91  Entry &E = Stack.back();
92  E.End = steady_clock::now();
93 
94  // Check that end times monotonically increase.
95  assert((Entries.empty() ||
96  (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
97  Entries.back().getFlameGraphStartUs(StartTime) +
98  Entries.back().getFlameGraphDurUs())) &&
99  "TimeProfiler scope ended earlier than previous scope");
100 
101  // Calculate duration at full precision for overall counts.
102  DurationType Duration = E.End - E.Start;
103 
104  // Only include sections longer or equal to TimeTraceGranularity msec.
105  if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
106  Entries.emplace_back(E);
107 
108  // Track total time taken by each "name", but only the topmost levels of
109  // them; e.g. if there's a template instantiation that instantiates other
110  // templates from within, we only want to add the topmost one. "topmost"
111  // happens to be the ones that don't have any currently open entries above
112  // itself.
114  [&](const Entry &Val) { return Val.Name == E.Name; })) {
115  auto &CountAndTotal = CountAndTotalPerName[E.Name];
116  CountAndTotal.first++;
117  CountAndTotal.second += Duration;
118  }
119 
120  Stack.pop_back();
121  }
122 
123  // Write events from this TimeTraceProfilerInstance and
124  // ThreadTimeTraceProfilerInstances.
126  // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
127  std::lock_guard<std::mutex> Lock(Mu);
128  assert(Stack.empty() &&
129  "All profiler sections should be ended when calling write");
131  [](const auto &TTP) { return TTP->Stack.empty(); }) &&
132  "All profiler sections should be ended when calling write");
133 
134  json::OStream J(OS);
135  J.objectBegin();
136  J.attributeBegin("traceEvents");
137  J.arrayBegin();
138 
139  // Emit all events for the main flame graph.
140  auto writeEvent = [&](const auto &E, uint64_t Tid) {
141  auto StartUs = E.getFlameGraphStartUs(StartTime);
142  auto DurUs = E.getFlameGraphDurUs();
143 
144  J.object([&] {
145  J.attribute("pid", Pid);
146  J.attribute("tid", int64_t(Tid));
147  J.attribute("ph", "X");
148  J.attribute("ts", StartUs);
149  J.attribute("dur", DurUs);
150  J.attribute("name", E.Name);
151  if (!E.Detail.empty()) {
152  J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
153  }
154  });
155  };
156  for (const Entry &E : Entries)
157  writeEvent(E, this->Tid);
159  for (const Entry &E : TTP->Entries)
160  writeEvent(E, TTP->Tid);
161 
162  // Emit totals by section name as additional "thread" events, sorted from
163  // longest one.
164  // Find highest used thread id.
165  uint64_t MaxTid = this->Tid;
167  MaxTid = std::max(MaxTid, TTP->Tid);
168 
169  // Combine all CountAndTotalPerName from threads into one.
170  StringMap<CountAndDurationType> AllCountAndTotalPerName;
171  auto combineStat = [&](const auto &Stat) {
172  StringRef Key = Stat.getKey();
173  auto Value = Stat.getValue();
174  auto &CountAndTotal = AllCountAndTotalPerName[Key];
175  CountAndTotal.first += Value.first;
176  CountAndTotal.second += Value.second;
177  };
178  for (const auto &Stat : CountAndTotalPerName)
179  combineStat(Stat);
181  for (const auto &Stat : TTP->CountAndTotalPerName)
182  combineStat(Stat);
183 
184  std::vector<NameAndCountAndDurationType> SortedTotals;
185  SortedTotals.reserve(AllCountAndTotalPerName.size());
186  for (const auto &Total : AllCountAndTotalPerName)
187  SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue());
188 
189  llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A,
191  return A.second.second > B.second.second;
192  });
193 
194  // Report totals on separate threads of tracing file.
195  uint64_t TotalTid = MaxTid + 1;
196  for (const NameAndCountAndDurationType &Total : SortedTotals) {
197  auto DurUs = duration_cast<microseconds>(Total.second.second).count();
198  auto Count = AllCountAndTotalPerName[Total.first].first;
199 
200  J.object([&] {
201  J.attribute("pid", Pid);
202  J.attribute("tid", int64_t(TotalTid));
203  J.attribute("ph", "X");
204  J.attribute("ts", 0);
205  J.attribute("dur", DurUs);
206  J.attribute("name", "Total " + Total.first);
207  J.attributeObject("args", [&] {
208  J.attribute("count", int64_t(Count));
209  J.attribute("avg ms", int64_t(DurUs / Count / 1000));
210  });
211  });
212 
213  ++TotalTid;
214  }
215 
216  auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
217  StringRef arg) {
218  J.object([&] {
219  J.attribute("cat", "");
220  J.attribute("pid", Pid);
221  J.attribute("tid", int64_t(Tid));
222  J.attribute("ts", 0);
223  J.attribute("ph", "M");
224  J.attribute("name", Name);
225  J.attributeObject("args", [&] { J.attribute("name", arg); });
226  });
227  };
228 
229  writeMetadataEvent("process_name", Tid, ProcName);
230  writeMetadataEvent("thread_name", Tid, ThreadName);
232  writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
233 
234  J.arrayEnd();
235  J.attributeEnd();
236 
237  // Emit the absolute time when this TimeProfiler started.
238  // This can be used to combine the profiling data from
239  // multiple processes and preserve actual time intervals.
240  J.attribute("beginningOfTime",
241  time_point_cast<microseconds>(BeginningOfTime)
242  .time_since_epoch()
243  .count());
244 
245  J.objectEnd();
246  }
247 
251  const time_point<system_clock> BeginningOfTime;
253  const std::string ProcName;
256  const uint64_t Tid;
257 
258  // Minimum time granularity (in microseconds)
259  const unsigned TimeTraceGranularity;
260 };
261 
262 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
263  StringRef ProcName) {
264  assert(TimeTraceProfilerInstance == nullptr &&
265  "Profiler should not be initialized");
267  TimeTraceGranularity, llvm::sys::path::filename(ProcName));
268 }
269 
270 // Removes all TimeTraceProfilerInstances.
271 // Called from main thread.
274  TimeTraceProfilerInstance = nullptr;
275  std::lock_guard<std::mutex> Lock(Mu);
276  for (auto *TTP : *ThreadTimeTraceProfilerInstances)
277  delete TTP;
279 }
280 
281 // Finish TimeTraceProfilerInstance on a worker thread.
282 // This doesn't remove the instance, just moves the pointer to global vector.
284  std::lock_guard<std::mutex> Lock(Mu);
286  TimeTraceProfilerInstance = nullptr;
287 }
288 
290  assert(TimeTraceProfilerInstance != nullptr &&
291  "Profiler object can't be null");
293 }
294 
296  StringRef FallbackFileName) {
297  assert(TimeTraceProfilerInstance != nullptr &&
298  "Profiler object can't be null");
299 
300  std::string Path = PreferredFileName.str();
301  if (Path.empty()) {
302  Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
303  Path += ".time-trace";
304  }
305 
306  std::error_code EC;
308  if (EC)
309  return createStringError(EC, "Could not open " + Path);
310 
312  return Error::success();
313 }
314 
316  if (TimeTraceProfilerInstance != nullptr)
317  TimeTraceProfilerInstance->begin(std::string(Name),
318  [&]() { return std::string(Detail); });
319 }
320 
322  llvm::function_ref<std::string()> Detail) {
323  if (TimeTraceProfilerInstance != nullptr)
324  TimeTraceProfilerInstance->begin(std::string(Name), Detail);
325 }
326 
328  if (TimeTraceProfilerInstance != nullptr)
330 }
llvm::json::OStream::attributeBegin
void attributeBegin(llvm::StringRef Key)
Definition: JSON.cpp:867
llvm
This is an optimization pass for GlobalISel generic memory operations.
Definition: AllocatorList.h:22
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:1606
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:264
ThreadTimeTraceProfilerInstances
static ManagedStatic< std::vector< TimeTraceProfiler * > > ThreadTimeTraceProfilerInstances
Definition: TimeProfiler.cpp:34
llvm::getTimeTraceProfilerInstance
TimeTraceProfiler * getTimeTraceProfilerInstance()
Definition: TimeProfiler.cpp:38
llvm::timeTraceProfilerWrite
void timeTraceProfilerWrite(raw_pwrite_stream &OS)
Write profiling data to output stream.
Definition: TimeProfiler.cpp:289
llvm::TimeTraceProfiler::TimeTraceGranularity
const unsigned TimeTraceGranularity
Definition: TimeProfiler.cpp:259
llvm::json::OStream::attributeEnd
void attributeEnd()
Definition: JSON.cpp:887
llvm::TimeTraceProfiler::StartTime
const TimePointType StartTime
Definition: TimeProfiler.cpp:252
llvm::timeTraceProfilerCleanup
void timeTraceProfilerCleanup()
Cleanup the time trace profiler, if it was initialized.
Definition: TimeProfiler.cpp:272
llvm::SmallVector< Entry, 16 >
Path.h
ManagedStatic.h
llvm::TimeTraceProfiler::ThreadName
SmallString< 0 > ThreadName
Definition: TimeProfiler.cpp:255
llvm::TimeTraceProfiler::CountAndTotalPerName
StringMap< CountAndDurationType > CountAndTotalPerName
Definition: TimeProfiler.cpp:250
llvm::reverse
auto reverse(ContainerTy &&C, std::enable_if_t< has_rbegin< ContainerTy >::value > *=nullptr)
Definition: STLExtras.h:357
llvm::TimeTraceProfiler::end
void end()
Definition: TimeProfiler.cpp:89
llvm::TimeTraceProfiler::Tid
const uint64_t Tid
Definition: TimeProfiler.cpp:256
llvm::sys::Process::Pid
int32_t Pid
Definition: Process.h:46
llvm::timeTraceProfilerFinishThread
void timeTraceProfilerFinishThread()
Finish a time trace profiler running on a worker thread.
Definition: TimeProfiler.cpp:283
llvm::timeTraceProfilerInitialize
void timeTraceProfilerInitialize(unsigned TimeTraceGranularity, StringRef ProcName)
Initialize the time trace profiler.
Definition: TimeProfiler.cpp:262
llvm::sys::Process
A collection of legacy interfaces for querying information about the current executing process.
Definition: Process.h:44
llvm::Lock
static sys::Mutex Lock
Definition: NVPTXUtilities.cpp:39
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:1592
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:542
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:951
llvm::timeTraceProfilerBegin
void timeTraceProfilerBegin(StringRef Name, StringRef Detail)
Manually begin a time section, with the given Name and Detail.
Definition: TimeProfiler.cpp:315
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:253
llvm::ManagedStatic
ManagedStatic - This transparently changes the behavior of global statics to be lazily constructed on...
Definition: ManagedStatic.h:83
llvm::AMDGPU::PALMD::Key
Key
PAL metadata keys.
Definition: AMDGPUMetadata.h:481
B
static GCRegistry::Add< OcamlGC > B("ocaml", "ocaml 3.10-compatible GC")
Mu
static std::mutex Mu
Definition: TimeProfiler.cpp:31
llvm::get_thread_name
void get_thread_name(SmallVectorImpl< char > &Name)
Get the name of the current thread.
STLFunctionalExtras.h
JSON.h
StringMap.h
llvm::StringRef::str
LLVM_NODISCARD std::string str() const
str - Get the contents as an std::string.
Definition: StringRef.h:245
llvm::json::OStream::objectEnd
void objectEnd()
Definition: JSON.cpp:856
now
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
Definition: ArchiveWriter.cpp:261
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::function_ref
An efficient, type-erasing, non-owning reference to a callable.
Definition: STLFunctionalExtras.h:36
llvm::TimeTraceProfiler
Definition: TimeProfiler.cpp:76
llvm::TimeTraceProfiler::begin
void begin(std::string Name, llvm::function_ref< std::string()> Detail)
Definition: TimeProfiler.cpp:84
Threading.h
llvm::json::OStream
json::OStream allows writing well-formed JSON without materializing all structures as json::Value ahe...
Definition: JSON.h:921
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:1675
uint64_t
llvm::raw_pwrite_stream
An abstract base class for streams implementations that also support a pwrite operation.
Definition: raw_ostream.h:418
llvm::TimeTraceProfiler::BeginningOfTime
const time_point< system_clock > BeginningOfTime
Definition: TimeProfiler.cpp:251
llvm::TimeTraceProfiler::write
void write(raw_pwrite_stream &OS)
Definition: TimeProfiler.cpp:125
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:829
llvm::TimeTraceProfiler::Entries
SmallVector< Entry, 128 > Entries
Definition: TimeProfiler.cpp:249
llvm::TimeTraceProfiler::Stack
SmallVector< Entry, 16 > Stack
Definition: TimeProfiler.cpp:248
assert
assert(ImpDefSCC.getReg()==AMDGPU::SCC &&ImpDefSCC.isDef())
CountAndDurationType
std::pair< size_t, DurationType > CountAndDurationType
Definition: TimeProfiler.cpp:44
llvm::StringMapImpl::size
unsigned size() const
Definition: StringMap.h:94
TimePointType
time_point< steady_clock > TimePointType
Definition: TimeProfiler.cpp:43
llvm::StringRef
StringRef - Represent a constant reference to a string, i.e.
Definition: StringRef.h:58
DurationType
duration< steady_clock::rep, steady_clock::period > DurationType
Definition: TimeProfiler.cpp:42
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:444
llvm::TimeTraceProfiler::TimeTraceProfiler
TimeTraceProfiler(unsigned TimeTraceGranularity=0, StringRef ProcName="")
Definition: TimeProfiler.cpp:77
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
llvm::Error
Lightweight error class with error context and mandatory checking.
Definition: Error.h:155
llvm::sort
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1533
llvm::sys::path::filename
StringRef filename(StringRef path, Style style=Style::native)
Get filename.
Definition: Path.cpp:578
N
#define N
llvm::json::OStream::arrayEnd
void arrayEnd()
Definition: JSON.cpp:837
llvm::max
Align max(MaybeAlign Lhs, Align Rhs)
Definition: Alignment.h:340
TimeTraceProfilerInstance
static LLVM_THREAD_LOCAL TimeTraceProfiler * TimeTraceProfilerInstance
Definition: TimeProfiler.cpp:36
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:984
llvm::timeTraceProfilerEnd
void timeTraceProfilerEnd()
Manually end the last time section.
Definition: TimeProfiler.cpp:327
NameAndCountAndDurationType
std::pair< std::string, CountAndDurationType > NameAndCountAndDurationType
Definition: TimeProfiler.cpp:46
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:976
llvm::TimeTraceProfiler::Pid
const sys::Process::Pid Pid
Definition: TimeProfiler.cpp:254
llvm::json::OStream::objectBegin
void objectBegin()
Definition: JSON.cpp:848
llvm::Value
LLVM Value Representation.
Definition: Value.h:74
TimeProfiler.h