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