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