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