src/tools/gn/trace.cc

   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
  20 namespace {
  21
  22 class 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
  45 TraceLog* trace_log = NULL;
  46
  47 struct 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
  55 bool DurationGreater(const TraceItem* a, const TraceItem* b) {
  56   return a->delta() > b->delta();
  57 }
  58
  59 bool CoalescedDurationGreater(const Coalesced& a, const Coalesced& b) {
  60   return a.total_duration > b.total_duration;
  61 }
  62
  63 void 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
  76 void 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
 101 void 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
 107 void 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
 115 TraceItem::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
 123 TraceItem::~TraceItem() {
 124 }
 125
 126 ScopedTrace::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
 135 ScopedTrace::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
 145 ScopedTrace::~ScopedTrace() {
 146   Done();
 147 }
 148
 149 void ScopedTrace::SetToolchain(const Label& label) {
 150   if (item_)
 151     item_->set_toolchain(label.GetUserVisibleName(false));
 152 }
 153
 154 void ScopedTrace::SetCommandLine(const CommandLine& cmdline) {
 155   if (item_)
 156     item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
 157 }
 158
 159 void 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
 169 void EnableTracing() {
 170   if (!trace_log)
 171     trace_log = new TraceLog;
 172 }
 173
 174 void AddTrace(TraceItem* item) {
 175   trace_log->Add(item);
 176 }
 177
 178 std::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
 239 void 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 }