trace.cc revision effb81e5f8246d0db0270817048dc992db66e9fb 
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/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  CHECK(!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  for (size_t i = 0; i < events.size(); i++) {
189    switch (events[i]->type()) {
190      case TraceItem::TRACE_FILE_PARSE:
191        parses.push_back(events[i]);
192        break;
193      case TraceItem::TRACE_FILE_EXECUTE:
194        file_execs.push_back(events[i]);
195        break;
196      case TraceItem::TRACE_SCRIPT_EXECUTE:
197        script_execs.push_back(events[i]);
198        break;
199      case TraceItem::TRACE_FILE_LOAD:
200      case TraceItem::TRACE_FILE_WRITE:
201      case TraceItem::TRACE_DEFINE_TARGET:
202        break;  // Ignore these for the summary.
203    }
204  }
205
206  std::ostringstream out;
207  SummarizeParses(parses, out);
208  out << std::endl;
209  SummarizeFileExecs(file_execs, out);
210  out << std::endl;
211  SummarizeScriptExecs(script_execs, out);
212  out << std::endl;
213
214  return out.str();
215}
216
217void SaveTraces(const base::FilePath& file_name) {
218  std::ostringstream out;
219
220  out << "{\"traceEvents\":[";
221
222  std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
223
224  // Write main thread metadata (assume this is being written on the main
225  // thread).
226  out << "{\"pid\":0,\"tid\":" << base::PlatformThread::CurrentId();
227  out << ",\"ts\":0,\"ph\":\"M\",";
228  out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
229
230  std::vector<TraceItem*> events = trace_log->events();
231  for (size_t i = 0; i < events.size(); i++) {
232    const TraceItem& item = *events[i];
233
234    if (i != 0)
235      out << ",";
236    out << "{\"pid\":0,\"tid\":" << item.thread_id();
237    out << ",\"ts\":" << item.begin().ToInternalValue();
238    out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
239    out << ",\"dur\":" << item.delta().InMicroseconds();
240
241    quote_buffer.resize(0);
242    base::EscapeJSONString(item.name(), true, &quote_buffer);
243    out << ",\"name\":" << quote_buffer;
244
245    out << ",\"cat\":";
246    switch (item.type()) {
247      case TraceItem::TRACE_FILE_LOAD:
248        out << "\"load\"";
249        break;
250      case TraceItem::TRACE_FILE_PARSE:
251        out << "\"parse\"";
252        break;
253      case TraceItem::TRACE_FILE_EXECUTE:
254        out << "\"file_exec\"";
255        break;
256      case TraceItem::TRACE_FILE_WRITE:
257        out << "\"file_write\"";
258        break;
259      case TraceItem::TRACE_SCRIPT_EXECUTE:
260        out << "\"script_exec\"";
261        break;
262      case TraceItem::TRACE_DEFINE_TARGET:
263        out << "\"define\"";
264    }
265
266    if (!item.toolchain().empty() || !item.cmdline().empty()) {
267      out << ",\"args\":{";
268      bool needs_comma = false;
269      if (!item.toolchain().empty()) {
270        quote_buffer.resize(0);
271        base::EscapeJSONString(item.toolchain(), true, &quote_buffer);
272        out << "\"toolchain\":" << quote_buffer;
273        needs_comma = true;
274      }
275      if (!item.cmdline().empty()) {
276        quote_buffer.resize(0);
277        base::EscapeJSONString(item.cmdline(), true, &quote_buffer);
278        if (needs_comma)
279          out << ",";
280        out << "\"cmdline\":" << quote_buffer;
281        needs_comma = true;
282      }
283      out << "}";
284    }
285    out << "}";
286  }
287
288  out << "]}";
289
290  std::string out_str = out.str();
291  base::WriteFile(file_name, out_str.data(),
292                       static_cast<int>(out_str.size()));
293}
294