trace.cc revision 5d1f7b1de12d16ceb2c938c56701a3e8bfa558f7 
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  ~TraceLog() {
28    // Trace items leanked intentionally.
29  }
30
31  void Add(TraceItem* item) {
32    base::AutoLock lock(lock_);
33    events_.push_back(item);
34  }
35
36  // Returns a copy for threadsafety.
37  std::vector<TraceItem*> events() const { return events_; }
38
39 private:
40  base::Lock lock_;
41
42  std::vector<TraceItem*> events_;
43
44  DISALLOW_COPY_AND_ASSIGN(TraceLog);
45};
46
47TraceLog* trace_log = NULL;
48
49struct Coalesced {
50  Coalesced() : name_ptr(NULL), total_duration(0.0), count(0) {}
51
52  const std::string* name_ptr;  // Pointer to a string with the name in it.
53  double total_duration;
54  int count;
55};
56
57bool DurationGreater(const TraceItem* a, const TraceItem* b) {
58  return a->delta() > b->delta();
59}
60
61bool CoalescedDurationGreater(const Coalesced& a, const Coalesced& b) {
62  return a.total_duration > b.total_duration;
63}
64
65void SummarizeParses(std::vector<const TraceItem*>& loads,
66                     std::ostream& out) {
67  out << "File parse times: (time in ms, name)\n";
68
69  std::sort(loads.begin(), loads.end(), &DurationGreater);
70
71  for (size_t i = 0; i < loads.size(); i++) {
72    out << base::StringPrintf(" %8.2f  ",
73                              loads[i]->delta().InMillisecondsF());
74    out << loads[i]->name() << std::endl;
75  }
76}
77
78void SummarizeCoalesced(std::vector<const TraceItem*>& items,
79                        std::ostream& out) {
80  // Group by file name.
81  std::map<std::string, Coalesced> coalesced;
82  for (size_t i = 0; i < items.size(); i++) {
83    Coalesced& c = coalesced[items[i]->name()];
84    c.name_ptr = &items[i]->name();
85    c.total_duration += items[i]->delta().InMillisecondsF();
86    c.count++;
87  }
88
89  // Sort by duration.
90  std::vector<Coalesced> sorted;
91  for (std::map<std::string, Coalesced>::iterator iter = coalesced.begin();
92       iter != coalesced.end(); ++iter)
93    sorted.push_back(iter->second);
94  std::sort(sorted.begin(), sorted.end(), &CoalescedDurationGreater);
95
96  for (size_t i = 0; i < sorted.size(); i++) {
97    out << base::StringPrintf(" %8.2f  %d  ",
98                              sorted[i].total_duration, sorted[i].count);
99    out << *sorted[i].name_ptr << std::endl;
100  }
101}
102
103void SummarizeFileExecs(std::vector<const TraceItem*>& execs,
104                        std::ostream& out) {
105  out << "File execute times: (total time in ms, # executions, name)\n";
106  SummarizeCoalesced(execs, out);
107}
108
109void SummarizeScriptExecs(std::vector<const TraceItem*>& execs,
110                          std::ostream& out) {
111  out << "Script execute times: (total time in ms, # executions, name)\n";
112  SummarizeCoalesced(execs, out);
113}
114
115}  // namespace
116
117TraceItem::TraceItem(Type type,
118                     const std::string& name,
119                     base::PlatformThreadId thread_id)
120    : type_(type),
121      name_(name),
122      thread_id_(thread_id) {
123}
124
125TraceItem::~TraceItem() {
126}
127
128ScopedTrace::ScopedTrace(TraceItem::Type t, const std::string& name)
129    : item_(NULL),
130      done_(false) {
131  if (trace_log) {
132    item_ = new TraceItem(t, name, base::PlatformThread::CurrentId());
133    item_->set_begin(base::TimeTicks::HighResNow());
134  }
135}
136
137ScopedTrace::ScopedTrace(TraceItem::Type t, const Label& label)
138    : item_(NULL),
139      done_(false) {
140  if (trace_log) {
141    item_ = new TraceItem(t, label.GetUserVisibleName(false),
142                          base::PlatformThread::CurrentId());
143    item_->set_begin(base::TimeTicks::HighResNow());
144  }
145}
146
147ScopedTrace::~ScopedTrace() {
148  Done();
149}
150
151void ScopedTrace::SetToolchain(const Label& label) {
152  if (item_)
153    item_->set_toolchain(label.GetUserVisibleName(false));
154}
155
156void ScopedTrace::SetCommandLine(const CommandLine& cmdline) {
157  if (item_)
158    item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
159}
160
161void ScopedTrace::Done() {
162  if (!done_) {
163    done_ = true;
164    if (trace_log) {
165      item_->set_end(base::TimeTicks::HighResNow());
166      AddTrace(item_);
167    }
168  }
169}
170
171void EnableTracing() {
172  CHECK(!trace_log);
173  trace_log = new TraceLog;
174}
175
176void AddTrace(TraceItem* item) {
177  trace_log->Add(item);
178}
179
180std::string SummarizeTraces() {
181  if (!trace_log)
182    return std::string();
183
184  std::vector<TraceItem*> events = trace_log->events();
185
186  // Classify all events.
187  std::vector<const TraceItem*> parses;
188  std::vector<const TraceItem*> file_execs;
189  std::vector<const TraceItem*> script_execs;
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_FILE_LOAD:
202      case TraceItem::TRACE_FILE_WRITE:
203      case TraceItem::TRACE_DEFINE_TARGET:
204        break;  // Ignore these for the summary.
205    }
206  }
207
208  std::ostringstream out;
209  SummarizeParses(parses, out);
210  out << std::endl;
211  SummarizeFileExecs(file_execs, out);
212  out << std::endl;
213  SummarizeScriptExecs(script_execs, out);
214  out << std::endl;
215
216  return out.str();
217}
218
219void SaveTraces(const base::FilePath& file_name) {
220  std::ostringstream out;
221
222  out << "{\"traceEvents\":[";
223
224  std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
225
226  // Write main thread metadata (assume this is being written on the main
227  // thread).
228  out << "{\"pid\":0,\"tid\":" << base::PlatformThread::CurrentId();
229  out << ",\"ts\":0,\"ph\":\"M\",";
230  out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
231
232  std::vector<TraceItem*> events = trace_log->events();
233  for (size_t i = 0; i < events.size(); i++) {
234    const TraceItem& item = *events[i];
235
236    if (i != 0)
237      out << ",";
238    out << "{\"pid\":0,\"tid\":" << item.thread_id();
239    out << ",\"ts\":" << item.begin().ToInternalValue();
240    out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
241    out << ",\"dur\":" << item.delta().InMicroseconds();
242
243    quote_buffer.resize(0);
244    base::EscapeJSONString(item.name(), true, &quote_buffer);
245    out << ",\"name\":" << quote_buffer;
246
247    out << ",\"cat\":";
248    switch (item.type()) {
249      case TraceItem::TRACE_FILE_LOAD:
250        out << "\"load\"";
251        break;
252      case TraceItem::TRACE_FILE_PARSE:
253        out << "\"parse\"";
254        break;
255      case TraceItem::TRACE_FILE_EXECUTE:
256        out << "\"file_exec\"";
257        break;
258      case TraceItem::TRACE_FILE_WRITE:
259        out << "\"file_write\"";
260        break;
261      case TraceItem::TRACE_SCRIPT_EXECUTE:
262        out << "\"script_exec\"";
263        break;
264      case TraceItem::TRACE_DEFINE_TARGET:
265        out << "\"define\"";
266    }
267
268    if (!item.toolchain().empty() || !item.cmdline().empty()) {
269      out << ",\"args\":{";
270      bool needs_comma = false;
271      if (!item.toolchain().empty()) {
272        quote_buffer.resize(0);
273        base::EscapeJSONString(item.toolchain(), true, &quote_buffer);
274        out << "\"toolchain\":" << quote_buffer;
275        needs_comma = true;
276      }
277      if (!item.cmdline().empty()) {
278        quote_buffer.resize(0);
279        base::EscapeJSONString(item.cmdline(), true, &quote_buffer);
280        if (needs_comma)
281          out << ",";
282        out << "\"cmdline\":" << quote_buffer;
283        needs_comma = true;
284      }
285      out << "}";
286    }
287    out << "}";
288  }
289
290  out << "]}";
291
292  std::string out_str = out.str();
293  file_util::WriteFile(file_name, out_str.data(),
294                       static_cast<int>(out_str.size()));
295}
296