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/StringMap.h"
15 #include "llvm/Support/CommandLine.h"
16 #include "llvm/Support/FileSystem.h"
17 #include "llvm/Support/JSON.h"
18 #include <cassert>
19 #include <chrono>
20 #include <string>
21 #include <vector>
22 
23 using namespace std::chrono;
24 
25 namespace llvm {
26 
27 TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
28 
29 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
30 typedef time_point<steady_clock> TimePointType;
31 typedef std::pair<size_t, DurationType> CountAndDurationType;
32 typedef std::pair<std::string, CountAndDurationType>
33     NameAndCountAndDurationType;
34 
35 struct Entry {
36   TimePointType Start;
37   TimePointType End;
38   std::string Name;
39   std::string Detail;
40 
41   Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
42       : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
43         Detail(std::move(Dt)){};
44 
45   // Calculate timings for FlameGraph. Cast time points to microsecond precision
46   // rather than casting duration. This avoid truncation issues causing inner
47   // scopes overruning outer scopes.
48   steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
49     return (time_point_cast<microseconds>(Start) -
50             time_point_cast<microseconds>(StartTime))
51         .count();
52   }
53 
54   steady_clock::rep getFlameGraphDurUs() const {
55     return (time_point_cast<microseconds>(End) -
56             time_point_cast<microseconds>(Start))
57         .count();
58   }
59 };
60 
61 struct TimeTraceProfiler {
62   TimeTraceProfiler(unsigned TimeTraceGranularity = 0)
63       : TimeTraceGranularity(TimeTraceGranularity) {
64     StartTime = steady_clock::now();
65   }
66 
67   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
68     Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
69                        Detail());
70   }
71 
72   void end() {
73     assert(!Stack.empty() && "Must call begin() first");
74     auto &E = Stack.back();
75     E.End = steady_clock::now();
76 
77     // Check that end times monotonically increase.
78     assert((Entries.empty() ||
79             (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
80              Entries.back().getFlameGraphStartUs(StartTime) +
81                  Entries.back().getFlameGraphDurUs())) &&
82            "TimeProfiler scope ended earlier than previous scope");
83 
84     // Calculate duration at full precision for overall counts.
85     DurationType Duration = E.End - E.Start;
86 
87     // Only include sections longer or equal to TimeTraceGranularity msec.
88     if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
89       Entries.emplace_back(E);
90 
91     // Track total time taken by each "name", but only the topmost levels of
92     // them; e.g. if there's a template instantiation that instantiates other
93     // templates from within, we only want to add the topmost one. "topmost"
94     // happens to be the ones that don't have any currently open entries above
95     // itself.
96     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
97           return Val.Name == E.Name;
98         }) == Stack.rend()) {
99       auto &CountAndTotal = CountAndTotalPerName[E.Name];
100       CountAndTotal.first++;
101       CountAndTotal.second += Duration;
102     }
103 
104     Stack.pop_back();
105   }
106 
107   void Write(raw_pwrite_stream &OS) {
108     assert(Stack.empty() &&
109            "All profiler sections should be ended when calling Write");
110     json::OStream J(OS);
111     J.objectBegin();
112     J.attributeBegin("traceEvents");
113     J.arrayBegin();
114 
115     // Emit all events for the main flame graph.
116     for (const auto &E : Entries) {
117       auto StartUs = E.getFlameGraphStartUs(StartTime);
118       auto DurUs = E.getFlameGraphDurUs();
119 
120       J.object([&]{
121         J.attribute("pid", 1);
122         J.attribute("tid", 0);
123         J.attribute("ph", "X");
124         J.attribute("ts", StartUs);
125         J.attribute("dur", DurUs);
126         J.attribute("name", E.Name);
127         J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
128       });
129     }
130 
131     // Emit totals by section name as additional "thread" events, sorted from
132     // longest one.
133     int Tid = 1;
134     std::vector<NameAndCountAndDurationType> SortedTotals;
135     SortedTotals.reserve(CountAndTotalPerName.size());
136     for (const auto &E : CountAndTotalPerName)
137       SortedTotals.emplace_back(E.getKey(), E.getValue());
138 
139     llvm::sort(SortedTotals.begin(), SortedTotals.end(),
140                [](const NameAndCountAndDurationType &A,
141                   const NameAndCountAndDurationType &B) {
142                  return A.second.second > B.second.second;
143                });
144     for (const auto &E : SortedTotals) {
145       auto DurUs = duration_cast<microseconds>(E.second.second).count();
146       auto Count = CountAndTotalPerName[E.first].first;
147 
148       J.object([&]{
149         J.attribute("pid", 1);
150         J.attribute("tid", Tid);
151         J.attribute("ph", "X");
152         J.attribute("ts", 0);
153         J.attribute("dur", DurUs);
154         J.attribute("name", "Total " + E.first);
155         J.attributeObject("args", [&] {
156           J.attribute("count", int64_t(Count));
157           J.attribute("avg ms", int64_t(DurUs / Count / 1000));
158         });
159       });
160 
161       ++Tid;
162     }
163 
164     // Emit metadata event with process name.
165     J.object([&] {
166       J.attribute("cat", "");
167       J.attribute("pid", 1);
168       J.attribute("tid", 0);
169       J.attribute("ts", 0);
170       J.attribute("ph", "M");
171       J.attribute("name", "process_name");
172       J.attributeObject("args", [&] { J.attribute("name", "clang"); });
173     });
174 
175     J.arrayEnd();
176     J.attributeEnd();
177     J.objectEnd();
178   }
179 
180   SmallVector<Entry, 16> Stack;
181   SmallVector<Entry, 128> Entries;
182   StringMap<CountAndDurationType> CountAndTotalPerName;
183   TimePointType StartTime;
184 
185   // Minimum time granularity (in microseconds)
186   unsigned TimeTraceGranularity;
187 };
188 
189 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity) {
190   assert(TimeTraceProfilerInstance == nullptr &&
191          "Profiler should not be initialized");
192   TimeTraceProfilerInstance = new TimeTraceProfiler(TimeTraceGranularity);
193 }
194 
195 void timeTraceProfilerCleanup() {
196   delete TimeTraceProfilerInstance;
197   TimeTraceProfilerInstance = nullptr;
198 }
199 
200 void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
201   assert(TimeTraceProfilerInstance != nullptr &&
202          "Profiler object can't be null");
203   TimeTraceProfilerInstance->Write(OS);
204 }
205 
206 void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
207   if (TimeTraceProfilerInstance != nullptr)
208     TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
209 }
210 
211 void timeTraceProfilerBegin(StringRef Name,
212                             llvm::function_ref<std::string()> Detail) {
213   if (TimeTraceProfilerInstance != nullptr)
214     TimeTraceProfilerInstance->begin(Name, Detail);
215 }
216 
217 void timeTraceProfilerEnd() {
218   if (TimeTraceProfilerInstance != nullptr)
219     TimeTraceProfilerInstance->end();
220 }
221 
222 } // namespace llvm
223