1 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "gn/trace.h"
6
7 #include <stddef.h>
8
9 #include <algorithm>
10 #include <map>
11 #include <mutex>
12 #include <sstream>
13 #include <vector>
14
15 #include "base/command_line.h"
16 #include "base/files/file_path.h"
17 #include "base/files/file_util.h"
18 #include "base/json/string_escape.h"
19 #include "base/logging.h"
20 #include "base/macros.h"
21 #include "base/strings/stringprintf.h"
22 #include "gn/filesystem_utils.h"
23 #include "gn/label.h"
24
25 namespace {
26
27 constexpr uint64_t kNanosecondsToMicroseconds = 1'000;
28
29 class TraceLog {
30 public:
TraceLog()31 TraceLog() { events_.reserve(16384); }
32 // Trace items leaked intentionally.
33
Add(TraceItem * item)34 void Add(TraceItem* item) {
35 std::lock_guard<std::mutex> lock(lock_);
36 events_.push_back(item);
37 }
38
39 // Returns a copy for threadsafety.
events() const40 std::vector<TraceItem*> events() const { return events_; }
41
42 private:
43 std::mutex lock_;
44
45 std::vector<TraceItem*> events_;
46
47 DISALLOW_COPY_AND_ASSIGN(TraceLog);
48 };
49
50 TraceLog* trace_log = nullptr;
51
52 struct Coalesced {
Coalesced__anon9144b3e90111::Coalesced53 Coalesced() : name_ptr(nullptr), total_duration(0.0), count(0) {}
54
55 const std::string* name_ptr; // Pointer to a string with the name in it.
56 double total_duration;
57 int count;
58 };
59
DurationGreater(const TraceItem * a,const TraceItem * b)60 bool DurationGreater(const TraceItem* a, const TraceItem* b) {
61 return a->delta().raw() > b->delta().raw();
62 }
63
CoalescedDurationGreater(const Coalesced & a,const Coalesced & b)64 bool CoalescedDurationGreater(const Coalesced& a, const Coalesced& b) {
65 return a.total_duration > b.total_duration;
66 }
67
SummarizeParses(std::vector<const TraceItem * > & loads,std::ostream & out)68 void SummarizeParses(std::vector<const TraceItem*>& loads, std::ostream& out) {
69 out << "File parse times: (time in ms, name)\n";
70
71 std::sort(loads.begin(), loads.end(), &DurationGreater);
72 for (auto* load : loads) {
73 out << base::StringPrintf(" %8.2f ", load->delta().InMillisecondsF());
74 out << load->name() << std::endl;
75 }
76 }
77
SummarizeCoalesced(std::vector<const TraceItem * > & items,std::ostream & out)78 void SummarizeCoalesced(std::vector<const TraceItem*>& items,
79 std::ostream& out) {
80 // Group by file name.
81 std::map<std::string, Coalesced> coalesced;
82 for (auto* item : items) {
83 Coalesced& c = coalesced[item->name()];
84 c.name_ptr = &item->name();
85 c.total_duration += item->delta().InMillisecondsF();
86 c.count++;
87 }
88
89 // Sort by duration.
90 std::vector<Coalesced> sorted;
91 for (const auto& pair : coalesced)
92 sorted.push_back(pair.second);
93 std::sort(sorted.begin(), sorted.end(), &CoalescedDurationGreater);
94
95 for (const auto& cur : sorted) {
96 out << base::StringPrintf(" %8.2f %d ", cur.total_duration, cur.count);
97 out << *cur.name_ptr << std::endl;
98 }
99 }
100
SummarizeFileExecs(std::vector<const TraceItem * > & execs,std::ostream & out)101 void SummarizeFileExecs(std::vector<const TraceItem*>& execs,
102 std::ostream& out) {
103 out << "File execute times: (total time in ms, # executions, name)\n";
104 SummarizeCoalesced(execs, out);
105 }
106
SummarizeScriptExecs(std::vector<const TraceItem * > & execs,std::ostream & out)107 void SummarizeScriptExecs(std::vector<const TraceItem*>& execs,
108 std::ostream& out) {
109 out << "Script execute times: (total time in ms, # executions, name)\n";
110 SummarizeCoalesced(execs, out);
111 }
112
113 } // namespace
114
TraceItem(Type type,const std::string & name,std::thread::id thread_id)115 TraceItem::TraceItem(Type type,
116 const std::string& name,
117 std::thread::id thread_id)
118 : type_(type), name_(name), thread_id_(thread_id) {}
119
120 TraceItem::~TraceItem() = default;
121
ScopedTrace(TraceItem::Type t,const std::string & name)122 ScopedTrace::ScopedTrace(TraceItem::Type t, const std::string& name)
123 : item_(nullptr), done_(false) {
124 if (trace_log) {
125 item_ = new TraceItem(t, name, std::this_thread::get_id());
126 item_->set_begin(TicksNow());
127 }
128 }
129
ScopedTrace(TraceItem::Type t,const Label & label)130 ScopedTrace::ScopedTrace(TraceItem::Type t, const Label& label)
131 : item_(nullptr), done_(false) {
132 if (trace_log) {
133 item_ = new TraceItem(t, label.GetUserVisibleName(false),
134 std::this_thread::get_id());
135 item_->set_begin(TicksNow());
136 }
137 }
138
~ScopedTrace()139 ScopedTrace::~ScopedTrace() {
140 Done();
141 }
142
SetToolchain(const Label & label)143 void ScopedTrace::SetToolchain(const Label& label) {
144 if (item_)
145 item_->set_toolchain(label.GetUserVisibleName(false));
146 }
147
SetCommandLine(const base::CommandLine & cmdline)148 void ScopedTrace::SetCommandLine(const base::CommandLine& cmdline) {
149 if (item_)
150 item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
151 }
152
Done()153 void ScopedTrace::Done() {
154 if (!done_) {
155 done_ = true;
156 if (trace_log) {
157 item_->set_end(TicksNow());
158 AddTrace(item_);
159 }
160 }
161 }
162
EnableTracing()163 void EnableTracing() {
164 if (!trace_log)
165 trace_log = new TraceLog;
166 }
167
TracingEnabled()168 bool TracingEnabled() {
169 return !!trace_log;
170 }
171
AddTrace(TraceItem * item)172 void AddTrace(TraceItem* item) {
173 trace_log->Add(item);
174 }
175
SummarizeTraces()176 std::string SummarizeTraces() {
177 if (!trace_log)
178 return std::string();
179
180 std::vector<TraceItem*> events = trace_log->events();
181
182 // Classify all events.
183 std::vector<const TraceItem*> parses;
184 std::vector<const TraceItem*> file_execs;
185 std::vector<const TraceItem*> script_execs;
186 std::vector<const TraceItem*> check_headers;
187 int headers_checked = 0;
188 for (auto* event : events) {
189 switch (event->type()) {
190 case TraceItem::TRACE_FILE_PARSE:
191 parses.push_back(event);
192 break;
193 case TraceItem::TRACE_FILE_EXECUTE:
194 file_execs.push_back(event);
195 break;
196 case TraceItem::TRACE_SCRIPT_EXECUTE:
197 script_execs.push_back(event);
198 break;
199 case TraceItem::TRACE_CHECK_HEADERS:
200 check_headers.push_back(event);
201 break;
202 case TraceItem::TRACE_CHECK_HEADER:
203 headers_checked++;
204 break;
205 case TraceItem::TRACE_IMPORT_LOAD:
206 case TraceItem::TRACE_IMPORT_BLOCK:
207 case TraceItem::TRACE_SETUP:
208 case TraceItem::TRACE_FILE_LOAD:
209 case TraceItem::TRACE_FILE_WRITE:
210 case TraceItem::TRACE_DEFINE_TARGET:
211 case TraceItem::TRACE_ON_RESOLVED:
212 break; // Ignore these for the summary.
213 }
214 }
215
216 std::ostringstream out;
217 SummarizeParses(parses, out);
218 out << std::endl;
219 SummarizeFileExecs(file_execs, out);
220 out << std::endl;
221 SummarizeScriptExecs(script_execs, out);
222 out << std::endl;
223
224 // Generally there will only be one header check, but it's theoretically
225 // possible for more than one to run if more than one build is going in
226 // parallel. Just report the total of all of them.
227 if (!check_headers.empty()) {
228 double check_headers_time = 0;
229 for (auto* cur : check_headers)
230 check_headers_time += cur->delta().InMillisecondsF();
231
232 out << "Header check time: (total time in ms, files checked)\n";
233 out << base::StringPrintf(" %8.2f %d\n", check_headers_time,
234 headers_checked);
235 }
236
237 return out.str();
238 }
239
SaveTraces(const base::FilePath & file_name)240 void SaveTraces(const base::FilePath& file_name) {
241 std::ostringstream out;
242
243 out << "{\"traceEvents\":[";
244
245 std::string quote_buffer; // Allocate outside loop to prevent reallocationg.
246
247 // Write main thread metadata (assume this is being written on the main
248 // thread).
249 out << "{\"pid\":0,\"tid\":\"" << std::this_thread::get_id() << "\"";
250 out << ",\"ts\":0,\"ph\":\"M\",";
251 out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
252
253 std::vector<TraceItem*> events = trace_log->events();
254 for (size_t i = 0; i < events.size(); i++) {
255 const TraceItem& item = *events[i];
256
257 if (i != 0)
258 out << ",";
259 out << "{\"pid\":0,\"tid\":\"" << item.thread_id() << "\"";
260 out << ",\"ts\":" << item.begin() / kNanosecondsToMicroseconds;
261 out << ",\"ph\":\"X\""; // "X" = complete event with begin & duration.
262 out << ",\"dur\":" << item.delta().InMicroseconds();
263
264 quote_buffer.resize(0);
265 base::EscapeJSONString(item.name(), true, "e_buffer);
266 out << ",\"name\":" << quote_buffer;
267
268 out << ",\"cat\":";
269 switch (item.type()) {
270 case TraceItem::TRACE_SETUP:
271 out << "\"setup\"";
272 break;
273 case TraceItem::TRACE_FILE_LOAD:
274 out << "\"load\"";
275 break;
276 case TraceItem::TRACE_FILE_PARSE:
277 out << "\"parse\"";
278 break;
279 case TraceItem::TRACE_FILE_EXECUTE:
280 out << "\"file_exec\"";
281 break;
282 case TraceItem::TRACE_FILE_WRITE:
283 out << "\"file_write\"";
284 break;
285 case TraceItem::TRACE_IMPORT_LOAD:
286 out << "\"import_load\"";
287 break;
288 case TraceItem::TRACE_IMPORT_BLOCK:
289 out << "\"import_block\"";
290 break;
291 case TraceItem::TRACE_SCRIPT_EXECUTE:
292 out << "\"script_exec\"";
293 break;
294 case TraceItem::TRACE_DEFINE_TARGET:
295 out << "\"define\"";
296 break;
297 case TraceItem::TRACE_ON_RESOLVED:
298 out << "\"onresolved\"";
299 break;
300 case TraceItem::TRACE_CHECK_HEADER:
301 out << "\"hdr\"";
302 break;
303 case TraceItem::TRACE_CHECK_HEADERS:
304 out << "\"header_check\"";
305 break;
306 }
307
308 if (!item.toolchain().empty() || !item.cmdline().empty()) {
309 out << ",\"args\":{";
310 bool needs_comma = false;
311 if (!item.toolchain().empty()) {
312 quote_buffer.resize(0);
313 base::EscapeJSONString(item.toolchain(), true, "e_buffer);
314 out << "\"toolchain\":" << quote_buffer;
315 needs_comma = true;
316 }
317 if (!item.cmdline().empty()) {
318 quote_buffer.resize(0);
319 base::EscapeJSONString(item.cmdline(), true, "e_buffer);
320 if (needs_comma)
321 out << ",";
322 out << "\"cmdline\":" << quote_buffer;
323 needs_comma = true;
324 }
325 out << "}";
326 }
327 out << "}";
328 }
329
330 out << "]}";
331
332 std::string out_str = out.str();
333 base::WriteFile(file_name, out_str.data(), static_cast<int>(out_str.size()));
334 }
335