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