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
13#include "llvm/Support/TimeProfiler.h"
14#include "llvm/ADT/STLExtras.h"
15#include "llvm/ADT/STLFunctionalExtras.h"
16#include "llvm/ADT/SmallVector.h"
17#include "llvm/ADT/StringMap.h"
18#include "llvm/Support/Compression.h"
19#include "llvm/Support/JSON.h"
20#include "llvm/Support/Path.h"
21#include "llvm/Support/Process.h"
22#include "llvm/Support/Threading.h"
23#include <algorithm>
24#include <cassert>
25#include <chrono>
26#include <memory>
27#include <mutex>
28#include <string>
29#include <vector>
30
31using namespace llvm;
32
33namespace {
34
35using std::chrono::duration;
36using std::chrono::duration_cast;
37using std::chrono::microseconds;
38using std::chrono::steady_clock;
39using std::chrono::system_clock;
40using std::chrono::time_point;
41using std::chrono::time_point_cast;
42
43struct TimeTraceProfilerInstances {
44 std::mutex Lock;
45 std::vector<TimeTraceProfiler *> List;
46};
47
48TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
49 static TimeTraceProfilerInstances Instances;
50 return Instances;
51}
52
53static const char TimeTraceFileExtension[] = ".time-trace.json";
54
55} // anonymous namespace
56
57// Per Thread instance
58static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
59
60TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
61 return TimeTraceProfilerInstance;
62}
63
64namespace {
65
66using ClockType = steady_clock;
67using TimePointType = time_point<ClockType>;
68using DurationType = duration<ClockType::rep, ClockType::period>;
69using CountAndDurationType = std::pair<size_t, DurationType>;
70using NameAndCountAndDurationType =
71 std::pair<std::string, CountAndDurationType>;
72
73} // anonymous namespace
74
75/// Represents an open or completed time section entry to be captured.
76struct llvm::TimeTraceProfilerEntry {
77 const TimePointType Start;
78 TimePointType End;
79 const std::string Name;
80 TimeTraceMetadata Metadata;
81
82 const TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent;
83 TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
84 std::string &&Dt, TimeTraceEventType Et)
85 : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(),
86 EventType(Et) {
87 Metadata.Detail = std::move(Dt);
88 }
89
90 TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
91 TimeTraceMetadata &&Mt, TimeTraceEventType Et)
92 : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
93 Metadata(std::move(Mt)), EventType(Et) {}
94
95 // Calculate timings for FlameGraph. Cast time points to microsecond precision
96 // rather than casting duration. This avoids truncation issues causing inner
97 // scopes overruning outer scopes.
98 ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
99 return (time_point_cast<microseconds>(t: Start) -
100 time_point_cast<microseconds>(t: StartTime))
101 .count();
102 }
103
104 ClockType::rep getFlameGraphDurUs() const {
105 return (time_point_cast<microseconds>(t: End) -
106 time_point_cast<microseconds>(t: Start))
107 .count();
108 }
109};
110
111// Represents a currently open (in-progress) time trace entry. InstantEvents
112// that happen during an open event are associated with the duration of this
113// parent event and they are dropped if parent duration is shorter than
114// the granularity.
115struct InProgressEntry {
116 TimeTraceProfilerEntry Event;
117 std::vector<TimeTraceProfilerEntry> InstantEvents;
118
119 InProgressEntry(TimePointType S, TimePointType E, std::string N,
120 std::string Dt, TimeTraceEventType Et)
121 : Event(std::move(S), std::move(E), std::move(N), std::move(Dt), Et),
122 InstantEvents() {}
123
124 InProgressEntry(TimePointType S, TimePointType E, std::string N,
125 TimeTraceMetadata Mt, TimeTraceEventType Et)
126 : Event(std::move(S), std::move(E), std::move(N), std::move(Mt), Et),
127 InstantEvents() {}
128};
129
130struct llvm::TimeTraceProfiler {
131 TimeTraceProfiler(
132 unsigned TimeTraceGranularity = 0, StringRef ProcName = "",
133 bool TimeTraceVerbose = false,
134 TimeTraceCompression TimeTraceCompress = TimeTraceCompression::Infer)
135 : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
136 ProcName(ProcName), Pid(sys::Process::getProcessId()),
137 Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity),
138 TimeTraceVerbose(TimeTraceVerbose),
139 TimeTraceCompress(TimeTraceCompress) {
140 llvm::get_thread_name(Name&: ThreadName);
141 }
142
143 TimeTraceProfilerEntry *
144 begin(std::string Name, llvm::function_ref<std::string()> Detail,
145 TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) {
146 assert(EventType != TimeTraceEventType::InstantEvent &&
147 "Instant Events don't have begin and end.");
148 Stack.emplace_back(Args: std::make_unique<InProgressEntry>(
149 args: ClockType::now(), args: TimePointType(), args: std::move(Name), args: Detail(),
150 args&: EventType));
151 return &Stack.back()->Event;
152 }
153
154 TimeTraceProfilerEntry *
155 begin(std::string Name, llvm::function_ref<TimeTraceMetadata()> Metadata,
156 TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent) {
157 assert(EventType != TimeTraceEventType::InstantEvent &&
158 "Instant Events don't have begin and end.");
159 Stack.emplace_back(Args: std::make_unique<InProgressEntry>(
160 args: ClockType::now(), args: TimePointType(), args: std::move(Name), args: Metadata(),
161 args&: EventType));
162 return &Stack.back()->Event;
163 }
164
165 void insert(std::string Name, llvm::function_ref<std::string()> Detail) {
166 if (Stack.empty())
167 return;
168
169 Stack.back()->InstantEvents.emplace_back(args: TimeTraceProfilerEntry(
170 ClockType::now(), TimePointType(), std::move(Name), Detail(),
171 TimeTraceEventType::InstantEvent));
172 }
173
174 void end() {
175 assert(!Stack.empty() && "Must call begin() first");
176 end(E&: Stack.back()->Event);
177 }
178
179 void end(TimeTraceProfilerEntry &E) {
180 assert(!Stack.empty() && "Must call begin() first");
181 E.End = ClockType::now();
182
183 // Calculate duration at full precision for overall counts.
184 DurationType Duration = E.End - E.Start;
185
186 const auto *Iter =
187 llvm::find_if(Range&: Stack, P: [&](const std::unique_ptr<InProgressEntry> &Val) {
188 return &Val->Event == &E;
189 });
190 assert(Iter != Stack.end() && "Event not in the Stack");
191
192 // Only include sections longer or equal to TimeTraceGranularity msec.
193 if (duration_cast<microseconds>(d: Duration).count() >= TimeTraceGranularity) {
194 Entries.emplace_back(Args&: E);
195 for (auto &IE : Iter->get()->InstantEvents) {
196 Entries.emplace_back(Args&: IE);
197 }
198 }
199
200 // Track total time taken by each "name", but only the topmost levels of
201 // them; e.g. if there's a template instantiation that instantiates other
202 // templates from within, we only want to add the topmost one. "topmost"
203 // happens to be the ones that don't have any currently open entries above
204 // itself.
205 if (llvm::none_of(Range: llvm::drop_begin(RangeOrContainer: llvm::reverse(C&: Stack)),
206 P: [&](const std::unique_ptr<InProgressEntry> &Val) {
207 return Val->Event.Name == E.Name;
208 })) {
209 auto &CountAndTotal = CountAndTotalPerName[E.Name];
210 CountAndTotal.first++;
211 CountAndTotal.second += Duration;
212 };
213
214 Stack.erase(CI: Iter);
215 }
216
217 // Write events from this TimeTraceProfilerInstance and
218 // ThreadTimeTraceProfilerInstances.
219 void write(raw_ostream &OS) {
220 // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
221 auto &Instances = getTimeTraceProfilerInstances();
222 std::lock_guard<std::mutex> Lock(Instances.Lock);
223 assert(Stack.empty() &&
224 "All profiler sections should be ended when calling write");
225 assert(llvm::all_of(Instances.List,
226 [](const auto &TTP) { return TTP->Stack.empty(); }) &&
227 "All profiler sections should be ended when calling write");
228
229 json::OStream J(OS);
230 J.objectBegin();
231 J.attributeBegin(Key: "traceEvents");
232 J.arrayBegin();
233
234 // Emit all events for the main flame graph.
235 auto writeEvent = [&](const auto &E, uint64_t Tid) {
236 auto StartUs = E.getFlameGraphStartUs(StartTime);
237 auto DurUs = E.getFlameGraphDurUs();
238
239 J.object(Contents: [&] {
240 J.attribute(Key: "pid", Contents: Pid);
241 J.attribute(Key: "tid", Contents: int64_t(Tid));
242 J.attribute(Key: "ts", Contents: StartUs);
243 if (E.EventType == TimeTraceEventType::AsyncEvent) {
244 J.attribute(Key: "cat", Contents: E.Name);
245 J.attribute(Key: "ph", Contents: "b");
246 J.attribute(Key: "id", Contents: 0);
247 } else if (E.EventType == TimeTraceEventType::CompleteEvent) {
248 J.attribute(Key: "ph", Contents: "X");
249 J.attribute(Key: "dur", Contents: DurUs);
250 } else { // instant event
251 assert(E.EventType == TimeTraceEventType::InstantEvent &&
252 "InstantEvent expected");
253 J.attribute(Key: "ph", Contents: "i");
254 }
255 J.attribute(Key: "name", Contents: E.Name);
256 if (!E.Metadata.isEmpty()) {
257 J.attributeObject(Key: "args", Contents: [&] {
258 if (!E.Metadata.Detail.empty())
259 J.attribute(Key: "detail", Contents: E.Metadata.Detail);
260 if (!E.Metadata.File.empty())
261 J.attribute(Key: "file", Contents: E.Metadata.File);
262 if (E.Metadata.Line > 0)
263 J.attribute(Key: "line", Contents: E.Metadata.Line);
264 });
265 }
266 });
267
268 if (E.EventType == TimeTraceEventType::AsyncEvent) {
269 J.object(Contents: [&] {
270 J.attribute(Key: "pid", Contents: Pid);
271 J.attribute(Key: "tid", Contents: int64_t(Tid));
272 J.attribute(Key: "ts", Contents: StartUs + DurUs);
273 J.attribute(Key: "cat", Contents: E.Name);
274 J.attribute(Key: "ph", Contents: "e");
275 J.attribute(Key: "id", Contents: 0);
276 J.attribute(Key: "name", Contents: E.Name);
277 });
278 }
279 };
280 for (const TimeTraceProfilerEntry &E : Entries)
281 writeEvent(E, this->Tid);
282 for (const TimeTraceProfiler *TTP : Instances.List)
283 for (const TimeTraceProfilerEntry &E : TTP->Entries)
284 writeEvent(E, TTP->Tid);
285
286 // Emit totals by section name as additional "thread" events, sorted from
287 // longest one.
288 // Find highest used thread id.
289 uint64_t MaxTid = this->Tid;
290 for (const TimeTraceProfiler *TTP : Instances.List)
291 MaxTid = std::max(a: MaxTid, b: TTP->Tid);
292
293 // Combine all CountAndTotalPerName from threads into one.
294 StringMap<CountAndDurationType> AllCountAndTotalPerName;
295 auto combineStat = [&](const auto &Stat) {
296 StringRef Key = Stat.getKey();
297 auto Value = Stat.getValue();
298 auto &CountAndTotal = AllCountAndTotalPerName[Key];
299 CountAndTotal.first += Value.first;
300 CountAndTotal.second += Value.second;
301 };
302 for (const auto &Stat : CountAndTotalPerName)
303 combineStat(Stat);
304 for (const TimeTraceProfiler *TTP : Instances.List)
305 for (const auto &Stat : TTP->CountAndTotalPerName)
306 combineStat(Stat);
307
308 std::vector<NameAndCountAndDurationType> SortedTotals;
309 SortedTotals.reserve(n: AllCountAndTotalPerName.size());
310 for (const auto &Total : AllCountAndTotalPerName)
311 SortedTotals.emplace_back(args: std::string(Total.getKey()), args: Total.getValue());
312
313 llvm::sort(C&: SortedTotals, Comp: [](const NameAndCountAndDurationType &A,
314 const NameAndCountAndDurationType &B) {
315 return A.second.second > B.second.second;
316 });
317
318 // Report totals on separate threads of tracing file.
319 uint64_t TotalTid = MaxTid + 1;
320 for (const NameAndCountAndDurationType &Total : SortedTotals) {
321 auto DurUs = duration_cast<microseconds>(d: Total.second.second).count();
322 auto Count = AllCountAndTotalPerName[Total.first].first;
323
324 J.object(Contents: [&] {
325 J.attribute(Key: "pid", Contents: Pid);
326 J.attribute(Key: "tid", Contents: int64_t(TotalTid));
327 J.attribute(Key: "ph", Contents: "X");
328 J.attribute(Key: "ts", Contents: 0);
329 J.attribute(Key: "dur", Contents: DurUs);
330 J.attribute(Key: "name", Contents: "Total " + Total.first);
331 J.attributeObject(Key: "args", Contents: [&] {
332 J.attribute(Key: "count", Contents: int64_t(Count));
333 J.attribute(Key: "avg ms", Contents: int64_t(DurUs / Count / 1000));
334 });
335 });
336
337 ++TotalTid;
338 }
339
340 auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
341 StringRef arg) {
342 J.object(Contents: [&] {
343 J.attribute(Key: "cat", Contents: "");
344 J.attribute(Key: "pid", Contents: Pid);
345 J.attribute(Key: "tid", Contents: int64_t(Tid));
346 J.attribute(Key: "ts", Contents: 0);
347 J.attribute(Key: "ph", Contents: "M");
348 J.attribute(Key: "name", Contents: Name);
349 J.attributeObject(Key: "args", Contents: [&] { J.attribute(Key: "name", Contents: arg); });
350 });
351 };
352
353 writeMetadataEvent("process_name", Tid, ProcName);
354 writeMetadataEvent("thread_name", Tid, ThreadName);
355 for (const TimeTraceProfiler *TTP : Instances.List)
356 writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
357
358 J.arrayEnd();
359 J.attributeEnd();
360
361 // Emit the absolute time when this TimeProfiler started.
362 // This can be used to combine the profiling data from
363 // multiple processes and preserve actual time intervals.
364 J.attribute(Key: "beginningOfTime",
365 Contents: time_point_cast<microseconds>(t: BeginningOfTime)
366 .time_since_epoch()
367 .count());
368
369 J.objectEnd();
370 }
371
372 SmallVector<std::unique_ptr<InProgressEntry>, 16> Stack;
373 SmallVector<TimeTraceProfilerEntry, 128> Entries;
374 StringMap<CountAndDurationType> CountAndTotalPerName;
375 // System clock time when the session was begun.
376 const time_point<system_clock> BeginningOfTime;
377 // Profiling clock time when the session was begun.
378 const TimePointType StartTime;
379 const std::string ProcName;
380 const sys::Process::Pid Pid;
381 SmallString<0> ThreadName;
382 const uint64_t Tid;
383
384 // Minimum time granularity (in microseconds)
385 const unsigned TimeTraceGranularity;
386
387 // Make time trace capture verbose event details (e.g. source filenames). This
388 // can increase the size of the output by 2-3 times.
389 const bool TimeTraceVerbose;
390
391 // Compression mode for output.
392 TimeTraceCompression TimeTraceCompress;
393};
394
395bool llvm::isTimeTraceVerbose() {
396 return getTimeTraceProfilerInstance() &&
397 getTimeTraceProfilerInstance()->TimeTraceVerbose;
398}
399
400TimeTraceCompression llvm::inferTimeTraceCompressionFromPath(StringRef Path) {
401 StringRef Ext = llvm::sys::path::extension(path: Path);
402 if (Ext.equals_insensitive(RHS: ".zst") || Ext.equals_insensitive(RHS: ".zstd"))
403 return TimeTraceCompression::Zstd;
404 return TimeTraceCompression::None;
405}
406
407void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
408 StringRef ProcName,
409 bool TimeTraceVerbose,
410 TimeTraceCompression TimeTraceCompress) {
411 assert(TimeTraceProfilerInstance == nullptr &&
412 "Profiler should not be initialized");
413 TimeTraceProfilerInstance = new TimeTraceProfiler(
414 TimeTraceGranularity, llvm::sys::path::filename(path: ProcName),
415 TimeTraceVerbose, TimeTraceCompress);
416}
417
418// Removes all TimeTraceProfilerInstances.
419// Called from main thread.
420void llvm::timeTraceProfilerCleanup() {
421 delete TimeTraceProfilerInstance;
422 TimeTraceProfilerInstance = nullptr;
423
424 auto &Instances = getTimeTraceProfilerInstances();
425 std::lock_guard<std::mutex> Lock(Instances.Lock);
426 for (auto *TTP : Instances.List)
427 delete TTP;
428 Instances.List.clear();
429}
430
431// Finish TimeTraceProfilerInstance on a worker thread.
432// This doesn't remove the instance, just moves the pointer to global vector.
433void llvm::timeTraceProfilerFinishThread() {
434 auto &Instances = getTimeTraceProfilerInstances();
435 std::lock_guard<std::mutex> Lock(Instances.Lock);
436 Instances.List.push_back(x: TimeTraceProfilerInstance);
437 TimeTraceProfilerInstance = nullptr;
438}
439
440void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) {
441 assert(TimeTraceProfilerInstance != nullptr &&
442 "Profiler object can't be null");
443 TimeTraceCompression CompressType =
444 TimeTraceProfilerInstance->TimeTraceCompress;
445 if (CompressType != TimeTraceCompression::Zstd) {
446 TimeTraceProfilerInstance->write(OS);
447 return;
448 }
449
450 compression::Format F = compression::Format::Zstd;
451 if (const char *Reason = compression::getReasonIfUnsupported(F))
452 report_fatal_error(reason: Reason);
453
454 SmallVector<char, 0> Uncompressed;
455 {
456 raw_svector_ostream UncompressedOS(Uncompressed);
457 TimeTraceProfilerInstance->write(OS&: UncompressedOS);
458 }
459 SmallVector<uint8_t, 0> Compressed;
460 compression::compress(
461 P: compression::Params(F),
462 Input: ArrayRef(reinterpret_cast<const uint8_t *>(Uncompressed.data()),
463 Uncompressed.size()),
464 Output&: Compressed);
465 OS.write(Ptr: reinterpret_cast<const char *>(Compressed.data()),
466 Size: Compressed.size());
467}
468
469Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
470 StringRef FallbackFileName) {
471 assert(TimeTraceProfilerInstance != nullptr &&
472 "Profiler object can't be null");
473
474 TimeTraceCompression CompressType =
475 TimeTraceProfilerInstance->TimeTraceCompress;
476 std::string Path = PreferredFileName.str();
477 if (Path.empty()) {
478 Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
479 Path += TimeTraceFileExtension;
480 if (CompressType == TimeTraceCompression::Zstd)
481 Path += ".zst";
482 } else if (CompressType == TimeTraceCompression::Infer) {
483 CompressType = inferTimeTraceCompressionFromPath(Path);
484 }
485
486 if (CompressType == TimeTraceCompression::Zstd) {
487 if (const char *Reason =
488 compression::getReasonIfUnsupported(F: compression::Format::Zstd))
489 return createStringError(EC: inconvertibleErrorCode(), S: Reason);
490 }
491
492 std::error_code EC;
493 sys::fs::OpenFlags Flags = CompressType == TimeTraceCompression::Zstd
494 ? sys::fs::OF_None
495 : sys::fs::OF_TextWithCRLF;
496 raw_fd_ostream OS(Path, EC, Flags);
497 if (EC)
498 return createStringError(EC, S: "Could not open " + Path);
499
500 TimeTraceCompression SavedCompress =
501 TimeTraceProfilerInstance->TimeTraceCompress;
502 TimeTraceProfilerInstance->TimeTraceCompress = CompressType;
503 timeTraceProfilerWrite(OS);
504 TimeTraceProfilerInstance->TimeTraceCompress = SavedCompress;
505 return Error::success();
506}
507
508TimeTraceProfilerEntry *llvm::timeTraceProfilerBegin(StringRef Name,
509 StringRef Detail) {
510 if (TimeTraceProfilerInstance != nullptr)
511 return TimeTraceProfilerInstance->begin(
512 Name: std::string(Name), Detail: [&]() { return std::string(Detail); },
513 EventType: TimeTraceEventType::CompleteEvent);
514 return nullptr;
515}
516
517TimeTraceProfilerEntry *
518llvm::timeTraceProfilerBegin(StringRef Name,
519 llvm::function_ref<std::string()> Detail) {
520 if (TimeTraceProfilerInstance != nullptr)
521 return TimeTraceProfilerInstance->begin(Name: std::string(Name), Detail,
522 EventType: TimeTraceEventType::CompleteEvent);
523 return nullptr;
524}
525
526TimeTraceProfilerEntry *
527llvm::timeTraceProfilerBegin(StringRef Name,
528 llvm::function_ref<TimeTraceMetadata()> Metadata) {
529 if (TimeTraceProfilerInstance != nullptr)
530 return TimeTraceProfilerInstance->begin(Name: std::string(Name), Metadata,
531 EventType: TimeTraceEventType::CompleteEvent);
532 return nullptr;
533}
534
535TimeTraceProfilerEntry *llvm::timeTraceAsyncProfilerBegin(StringRef Name,
536 StringRef Detail) {
537 if (TimeTraceProfilerInstance != nullptr)
538 return TimeTraceProfilerInstance->begin(
539 Name: std::string(Name), Detail: [&]() { return std::string(Detail); },
540 EventType: TimeTraceEventType::AsyncEvent);
541 return nullptr;
542}
543
544void llvm::timeTraceAddInstantEvent(StringRef Name,
545 llvm::function_ref<std::string()> Detail) {
546 if (TimeTraceProfilerInstance != nullptr)
547 TimeTraceProfilerInstance->insert(Name: std::string(Name), Detail);
548}
549
550void llvm::timeTraceProfilerEnd() {
551 if (TimeTraceProfilerInstance != nullptr)
552 TimeTraceProfilerInstance->end();
553}
554
555void llvm::timeTraceProfilerEnd(TimeTraceProfilerEntry *E) {
556 if (TimeTraceProfilerInstance != nullptr)
557 TimeTraceProfilerInstance->end(E&: *E);
558}
559