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