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