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 
14 #include "llvm/ADT/STLExtras.h"
15 #include "llvm/ADT/StringMap.h"
17 #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.
113  if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
114  return Val.Name == E.Name;
115  }) == Stack.rend()) {
116  auto &CountAndTotal = CountAndTotalPerName[E.Name];
117  CountAndTotal.first++;
118  CountAndTotal.second += Duration;
119  }
120 
121  Stack.pop_back();
122  }
123 
124  // Write events from this TimeTraceProfilerInstance and
125  // ThreadTimeTraceProfilerInstances.
127  // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
128  std::lock_guard<std::mutex> Lock(Mu);
129  assert(Stack.empty() &&
130  "All profiler sections should be ended when calling write");
132  [](const auto &TTP) { return TTP->Stack.empty(); }) &&
133  "All profiler sections should be ended when calling write");
134 
135  json::OStream J(OS);
136  J.objectBegin();
137  J.attributeBegin("traceEvents");
138  J.arrayBegin();
139 
140  // Emit all events for the main flame graph.
141  auto writeEvent = [&](const auto &E, uint64_t Tid) {
142  auto StartUs = E.getFlameGraphStartUs(StartTime);
143  auto DurUs = E.getFlameGraphDurUs();
144 
145  J.object([&] {
146  J.attribute("pid", Pid);
147  J.attribute("tid", int64_t(Tid));
148  J.attribute("ph", "X");
149  J.attribute("ts", StartUs);
150  J.attribute("dur", DurUs);
151  J.attribute("name", E.Name);
152  if (!E.Detail.empty()) {
153  J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
154  }
155  });
156  };
157  for (const Entry &E : Entries)
158  writeEvent(E, this->Tid);
160  for (const Entry &E : TTP->Entries)
161  writeEvent(E, TTP->Tid);
162 
163  // Emit totals by section name as additional "thread" events, sorted from
164  // longest one.
165  // Find highest used thread id.
166  uint64_t MaxTid = this->Tid;
168  MaxTid = std::max(MaxTid, TTP->Tid);
169 
170  // Combine all CountAndTotalPerName from threads into one.
171  StringMap<CountAndDurationType> AllCountAndTotalPerName;
172  auto combineStat = [&](const auto &Stat) {
173  StringRef Key = Stat.getKey();
174  auto Value = Stat.getValue();
175  auto &CountAndTotal = AllCountAndTotalPerName[Key];
176  CountAndTotal.first += Value.first;
177  CountAndTotal.second += Value.second;
178  };
179  for (const auto &Stat : CountAndTotalPerName)
180  combineStat(Stat);
182  for (const auto &Stat : TTP->CountAndTotalPerName)
183  combineStat(Stat);
184 
185  std::vector<NameAndCountAndDurationType> SortedTotals;
186  SortedTotals.reserve(AllCountAndTotalPerName.size());
187  for (const auto &Total : AllCountAndTotalPerName)
188  SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue());
189 
190  llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A,
192  return A.second.second > B.second.second;
193  });
194 
195  // Report totals on separate threads of tracing file.
196  uint64_t TotalTid = MaxTid + 1;
197  for (const NameAndCountAndDurationType &Total : SortedTotals) {
198  auto DurUs = duration_cast<microseconds>(Total.second.second).count();
199  auto Count = AllCountAndTotalPerName[Total.first].first;
200 
201  J.object([&] {
202  J.attribute("pid", Pid);
203  J.attribute("tid", int64_t(TotalTid));
204  J.attribute("ph", "X");
205  J.attribute("ts", 0);
206  J.attribute("dur", DurUs);
207  J.attribute("name", "Total " + Total.first);
208  J.attributeObject("args", [&] {
209  J.attribute("count", int64_t(Count));
210  J.attribute("avg ms", int64_t(DurUs / Count / 1000));
211  });
212  });
213 
214  ++TotalTid;
215  }
216 
217  auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
218  StringRef arg) {
219  J.object([&] {
220  J.attribute("cat", "");
221  J.attribute("pid", Pid);
222  J.attribute("tid", int64_t(Tid));
223  J.attribute("ts", 0);
224  J.attribute("ph", "M");
225  J.attribute("name", Name);
226  J.attributeObject("args", [&] { J.attribute("name", arg); });
227  });
228  };
229 
230  writeMetadataEvent("process_name", Tid, ProcName);
231  writeMetadataEvent("thread_name", Tid, ThreadName);
233  writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
234 
235  J.arrayEnd();
236  J.attributeEnd();
237 
238  // Emit the absolute time when this TimeProfiler started.
239  // This can be used to combine the profiling data from
240  // multiple processes and preserve actual time intervals.
241  J.attribute("beginningOfTime",
242  time_point_cast<microseconds>(BeginningOfTime)
243  .time_since_epoch()
244  .count());
245 
246  J.objectEnd();
247  }
248 
252  const time_point<system_clock> BeginningOfTime;
254  const std::string ProcName;
257  const uint64_t Tid;
258 
259  // Minimum time granularity (in microseconds)
260  const unsigned TimeTraceGranularity;
261 };
262 
263 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
264  StringRef ProcName) {
265  assert(TimeTraceProfilerInstance == nullptr &&
266  "Profiler should not be initialized");
268  TimeTraceGranularity, llvm::sys::path::filename(ProcName));
269 }
270 
271 // Removes all TimeTraceProfilerInstances.
272 // Called from main thread.
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:861
llvm
---------------------— PointerInfo ------------------------------------—
Definition: AllocatorList.h:23
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:260
llvm::json::OStream::attributeEnd
void attributeEnd()
Definition: JSON.cpp:881
llvm::TimeTraceProfiler::StartTime
const TimePointType StartTime
Definition: TimeProfiler.cpp:253
llvm::timeTraceProfilerCleanup
void timeTraceProfilerCleanup()
Cleanup the time trace profiler, if it was initialized.
Definition: TimeProfiler.cpp:273
llvm::SmallVector< Entry, 16 >
Path.h
llvm::TimeTraceProfiler::ThreadName
SmallString< 0 > ThreadName
Definition: TimeProfiler.cpp:256
llvm::TimeTraceProfiler::CountAndTotalPerName
StringMap< CountAndDurationType > CountAndTotalPerName
Definition: TimeProfiler.cpp:251
llvm::TimeTraceProfiler::end
void end()
Definition: TimeProfiler.cpp:89
llvm::TimeTraceProfiler::Tid
const uint64_t Tid
Definition: TimeProfiler.cpp:257
llvm::sys::Process::Pid
int32_t Pid
Definition: Process.h:46
STLExtras.h
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:263
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
CommandLine.h
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:1547
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:526
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:916
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::TimeTraceProfiler::ProcName
const std::string ProcName
Definition: TimeProfiler.cpp:254
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.
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:850
now
static sys::TimePoint< std::chrono::seconds > now(bool Deterministic)
Definition: ArchiveWriter.cpp:259
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: STLExtras.h:168
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:886
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:1630
uint64_t
llvm::raw_pwrite_stream
An abstract base class for streams implementations that also support a pwrite operation.
Definition: raw_ostream.h:417
llvm::TimeTraceProfiler::BeginningOfTime
const time_point< system_clock > BeginningOfTime
Definition: TimeProfiler.cpp:252
llvm::TimeTraceProfiler::write
void write(raw_pwrite_stream &OS)
Definition: TimeProfiler.cpp:126
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:823
llvm::TimeTraceProfiler::Entries
SmallVector< Entry, 128 > Entries
Definition: TimeProfiler.cpp:250
llvm::TimeTraceProfiler::Stack
SmallVector< Entry, 16 > Stack
Definition: TimeProfiler.cpp:249
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:93
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:443
llvm::find_if
auto find_if(R &&Range, UnaryPredicate P)
Provide wrappers to std::find_if which take ranges instead of having to pass begin/end explicitly.
Definition: STLExtras.h:1574
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:1231
llvm::GraphProgram::Name
Name
Definition: GraphWriter.h:52
llvm::Error
Lightweight error class with error context and mandatory checking.
Definition: Error.h:157
llvm::sort
void sort(IteratorTy Start, IteratorTy End)
Definition: STLExtras.h:1488
llvm::sys::path::filename
StringRef filename(StringRef path, Style style=Style::native)
Get filename.
Definition: Path.cpp:575
N
#define N
llvm::json::OStream::arrayEnd
void arrayEnd()
Definition: JSON.cpp:831
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:949
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:941
llvm::TimeTraceProfiler::Pid
const sys::Process::Pid Pid
Definition: TimeProfiler.cpp:255
llvm::json::OStream::objectBegin
void objectBegin()
Definition: JSON.cpp:842
llvm::Value
LLVM Value Representation.
Definition: Value.h:75
TimeProfiler.h