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/StringMap.h"
16 #include "llvm/Support/CommandLine.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
33 static std::vector<TimeTraceProfiler *>
34     ThreadTimeTraceProfilerInstances; // GUARDED_BY(Mu)
35 // Per Thread instance
36 static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
37 
38 TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
39   return TimeTraceProfilerInstance;
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>
46     NameAndCountAndDurationType;
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 
76 struct llvm::TimeTraceProfiler {
77   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
78       : StartTime(steady_clock::now()), ProcName(ProcName),
79         Pid(sys::Process::getProcessId()), Tid(llvm::get_threadid()),
80         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.
126   void write(raw_pwrite_stream &OS) {
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");
131     assert(llvm::all_of(ThreadTimeTraceProfilerInstances,
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);
159     for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances)
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;
167     for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances)
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);
181     for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances)
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,
191                                 const NameAndCountAndDurationType &B) {
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);
232     for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances)
233       writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
234 
235     J.arrayEnd();
236     J.attributeEnd();
237     J.objectEnd();
238   }
239 
240   SmallVector<Entry, 16> Stack;
241   SmallVector<Entry, 128> Entries;
242   StringMap<CountAndDurationType> CountAndTotalPerName;
243   const TimePointType StartTime;
244   const std::string ProcName;
245   const sys::Process::Pid Pid;
246   SmallString<0> ThreadName;
247   const uint64_t Tid;
248 
249   // Minimum time granularity (in microseconds)
250   const unsigned TimeTraceGranularity;
251 };
252 
253 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
254                                        StringRef ProcName) {
255   assert(TimeTraceProfilerInstance == nullptr &&
256          "Profiler should not be initialized");
257   TimeTraceProfilerInstance = new TimeTraceProfiler(
258       TimeTraceGranularity, llvm::sys::path::filename(ProcName));
259 }
260 
261 // Removes all TimeTraceProfilerInstances.
262 // Called from main thread.
263 void llvm::timeTraceProfilerCleanup() {
264   delete TimeTraceProfilerInstance;
265   std::lock_guard<std::mutex> Lock(Mu);
266   for (auto TTP : ThreadTimeTraceProfilerInstances)
267     delete TTP;
268   ThreadTimeTraceProfilerInstances.clear();
269 }
270 
271 // Finish TimeTraceProfilerInstance on a worker thread.
272 // This doesn't remove the instance, just moves the pointer to global vector.
273 void llvm::timeTraceProfilerFinishThread() {
274   std::lock_guard<std::mutex> Lock(Mu);
275   ThreadTimeTraceProfilerInstances.push_back(TimeTraceProfilerInstance);
276   TimeTraceProfilerInstance = nullptr;
277 }
278 
279 void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) {
280   assert(TimeTraceProfilerInstance != nullptr &&
281          "Profiler object can't be null");
282   TimeTraceProfilerInstance->write(OS);
283 }
284 
285 Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
286                                    StringRef FallbackFileName) {
287   assert(TimeTraceProfilerInstance != nullptr &&
288          "Profiler object can't be null");
289 
290   std::string Path = PreferredFileName.str();
291   if (Path.empty()) {
292     Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
293     Path += ".time-trace";
294   }
295 
296   std::error_code EC;
297   raw_fd_ostream OS(Path, EC, sys::fs::OF_Text);
298   if (EC)
299     return createStringError(EC, "Could not open " + Path);
300 
301   timeTraceProfilerWrite(OS);
302   return Error::success();
303 }
304 
305 void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
306   if (TimeTraceProfilerInstance != nullptr)
307     TimeTraceProfilerInstance->begin(std::string(Name),
308                                      [&]() { return std::string(Detail); });
309 }
310 
311 void llvm::timeTraceProfilerBegin(StringRef Name,
312                                   llvm::function_ref<std::string()> Detail) {
313   if (TimeTraceProfilerInstance != nullptr)
314     TimeTraceProfilerInstance->begin(std::string(Name), Detail);
315 }
316 
317 void llvm::timeTraceProfilerEnd() {
318   if (TimeTraceProfilerInstance != nullptr)
319     TimeTraceProfilerInstance->end();
320 }
321