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__anonb906e6a40111::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_LOAD:
215 case TraceItem::TRACE_FILE_WRITE:
216 case TraceItem::TRACE_DEFINE_TARGET:
217 case TraceItem::TRACE_ON_RESOLVED:
218 break; // Ignore these for the summary.
219 }
220 }
221
222 std::ostringstream out;
223 SummarizeParses(parses, out);
224 out << std::endl;
225 SummarizeFileExecs(file_execs, out);
226 out << std::endl;
227 SummarizeScriptExecs(script_execs, out);
228 out << std::endl;
229
230 // Generally there will only be one header check, but it's theoretically
231 // possible for more than one to run if more than one build is going in
232 // parallel. Just report the total of all of them.
233 if (!check_headers.empty()) {
234 double check_headers_time = 0;
235 for (auto* cur : check_headers)
236 check_headers_time += cur->delta().InMillisecondsF();
237
238 out << "Header check time: (total time in ms, files checked)\n";
239 out << base::StringPrintf(" %8.2f %d\n", check_headers_time,
240 headers_checked);
241 }
242
243 return out.str();
244 }
245
SaveTraces(const base::FilePath & file_name)246 void SaveTraces(const base::FilePath& file_name) {
247 std::ostringstream out;
248
249 out << "{\"traceEvents\":[";
250
251 std::string quote_buffer; // Allocate outside loop to prevent reallocationg.
252
253 // Trace viewer doesn't handle integer > 2^53 well, so re-numbering them to
254 // small numbers.
255 std::map<std::thread::id, int> tidmap;
256 std::vector<TraceItem*> events = trace_log->events();
257 for (const auto* item : events) {
258 int id = tidmap.size();
259 tidmap.emplace(item->thread_id(), id);
260 }
261
262 // Write main thread metadata (assume this is being written on the main
263 // thread).
264 out << "{\"pid\":0,\"tid\":\"" << tidmap[std::this_thread::get_id()] << "\"";
265 out << ",\"ts\":0,\"ph\":\"M\",";
266 out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
267
268 for (size_t i = 0; i < events.size(); i++) {
269 const TraceItem& item = *events[i];
270
271 if (i != 0)
272 out << ",";
273 out << "{\"pid\":0,\"tid\":\"" << tidmap[item.thread_id()] << "\"";
274 out << ",\"ts\":" << item.begin() / kNanosecondsToMicroseconds;
275 out << ",\"ph\":\"X\""; // "X" = complete event with begin & duration.
276 out << ",\"dur\":" << item.delta().InMicroseconds();
277
278 quote_buffer.resize(0);
279 base::EscapeJSONString(item.name(), true, "e_buffer);
280 out << ",\"name\":" << quote_buffer;
281
282 out << ",\"cat\":";
283 switch (item.type()) {
284 case TraceItem::TRACE_SETUP:
285 out << "\"setup\"";
286 break;
287 case TraceItem::TRACE_FILE_LOAD:
288 out << "\"load\"";
289 break;
290 case TraceItem::TRACE_FILE_PARSE:
291 out << "\"parse\"";
292 break;
293 case TraceItem::TRACE_FILE_EXECUTE:
294 out << "\"file_exec\"";
295 break;
296 case TraceItem::TRACE_FILE_WRITE:
297 out << "\"file_write\"";
298 break;
299 case TraceItem::TRACE_IMPORT_LOAD:
300 out << "\"import_load\"";
301 break;
302 case TraceItem::TRACE_IMPORT_BLOCK:
303 out << "\"import_block\"";
304 break;
305 case TraceItem::TRACE_SCRIPT_EXECUTE:
306 out << "\"script_exec\"";
307 break;
308 case TraceItem::TRACE_DEFINE_TARGET:
309 out << "\"define\"";
310 break;
311 case TraceItem::TRACE_ON_RESOLVED:
312 out << "\"onresolved\"";
313 break;
314 case TraceItem::TRACE_CHECK_HEADER:
315 out << "\"hdr\"";
316 break;
317 case TraceItem::TRACE_CHECK_HEADERS:
318 out << "\"header_check\"";
319 break;
320 }
321
322 if (!item.toolchain().empty() || !item.cmdline().empty()) {
323 out << ",\"args\":{";
324 bool needs_comma = false;
325 if (!item.toolchain().empty()) {
326 quote_buffer.resize(0);
327 base::EscapeJSONString(item.toolchain(), true, "e_buffer);
328 out << "\"toolchain\":" << quote_buffer;
329 needs_comma = true;
330 }
331 if (!item.cmdline().empty()) {
332 quote_buffer.resize(0);
333 base::EscapeJSONString(item.cmdline(), true, "e_buffer);
334 if (needs_comma)
335 out << ",";
336 out << "\"cmdline\":" << quote_buffer;
337 needs_comma = true;
338 }
339 out << "}";
340 }
341 out << "}";
342 }
343
344 out << "]}";
345
346 std::string out_str = out.str();
347 base::WriteFile(file_name, out_str.data(), static_cast<int>(out_str.size()));
348 }
349