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/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
  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   for (const auto& load : loads) {
  69     out << base::StringPrintf(" %8.2f  ", load->delta().InMillisecondsF());
  70     out << load->name() << std::endl;
  71   }
  72 }
  73
  74 void SummarizeCoalesced(std::vector<const TraceItem*>& items,
  75                         std::ostream& out) {
  76   // Group by file name.
  77   std::map<std::string, Coalesced> coalesced;
  78   for (const auto& item : items) {
  79     Coalesced& c = coalesced[item->name()];
  80     c.name_ptr = &item->name();
  81     c.total_duration += item->delta().InMillisecondsF();
  82     c.count++;
  83   }
  84
  85   // Sort by duration.
  86   std::vector<Coalesced> sorted;
  87   for (const auto& pair : coalesced)
  88     sorted.push_back(pair.second);
  89   std::sort(sorted.begin(), sorted.end(), &CoalescedDurationGreater);
  90
  91   for (const auto& cur : sorted) {
  92     out << base::StringPrintf(" %8.2f  %d  ", cur.total_duration, cur.count);
  93     out << *cur.name_ptr << std::endl;
  94   }
  95 }
  96
  97 void SummarizeFileExecs(std::vector<const TraceItem*>& execs,
  98                         std::ostream& out) {
  99   out << "File execute times: (total time in ms, # executions, name)\n";
 100   SummarizeCoalesced(execs, out);
 101 }
 102
 103 void SummarizeScriptExecs(std::vector<const TraceItem*>& execs,
 104                           std::ostream& out) {
 105   out << "Script execute times: (total time in ms, # executions, name)\n";
 106   SummarizeCoalesced(execs, out);
 107 }
 108
 109 }  // namespace
 110
 111 TraceItem::TraceItem(Type type,
 112                      const std::string& name,
 113                      base::PlatformThreadId thread_id)
 114     : type_(type),
 115       name_(name),
 116       thread_id_(thread_id) {
 117 }
 118
 119 TraceItem::~TraceItem() {
 120 }
 121
 122 ScopedTrace::ScopedTrace(TraceItem::Type t, const std::string& name)
 123     : item_(NULL),
 124       done_(false) {
 125   if (trace_log) {
 126     item_ = new TraceItem(t, name, base::PlatformThread::CurrentId());
 127     item_->set_begin(base::TimeTicks::HighResNow());
 128   }
 129 }
 130
 131 ScopedTrace::ScopedTrace(TraceItem::Type t, const Label& label)
 132     : item_(NULL),
 133       done_(false) {
 134   if (trace_log) {
 135     item_ = new TraceItem(t, label.GetUserVisibleName(false),
 136                           base::PlatformThread::CurrentId());
 137     item_->set_begin(base::TimeTicks::HighResNow());
 138   }
 139 }
 140
 141 ScopedTrace::~ScopedTrace() {
 142   Done();
 143 }
 144
 145 void ScopedTrace::SetToolchain(const Label& label) {
 146   if (item_)
 147     item_->set_toolchain(label.GetUserVisibleName(false));
 148 }
 149
 150 void ScopedTrace::SetCommandLine(const CommandLine& cmdline) {
 151   if (item_)
 152     item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
 153 }
 154
 155 void ScopedTrace::Done() {
 156   if (!done_) {
 157     done_ = true;
 158     if (trace_log) {
 159       item_->set_end(base::TimeTicks::HighResNow());
 160       AddTrace(item_);
 161     }
 162   }
 163 }
 164
 165 void EnableTracing() {
 166   if (!trace_log)
 167     trace_log = new TraceLog;
 168 }
 169
 170 void AddTrace(TraceItem* item) {
 171   trace_log->Add(item);
 172 }
 173
 174 std::string SummarizeTraces() {
 175   if (!trace_log)
 176     return std::string();
 177
 178   std::vector<TraceItem*> events = trace_log->events();
 179
 180   // Classify all events.
 181   std::vector<const TraceItem*> parses;
 182   std::vector<const TraceItem*> file_execs;
 183   std::vector<const TraceItem*> script_execs;
 184   std::vector<const TraceItem*> check_headers;
 185   int headers_checked = 0;
 186   for (const auto& event : events) {
 187     switch (event->type()) {
 188       case TraceItem::TRACE_FILE_PARSE:
 189         parses.push_back(event);
 190         break;
 191       case TraceItem::TRACE_FILE_EXECUTE:
 192         file_execs.push_back(event);
 193         break;
 194       case TraceItem::TRACE_SCRIPT_EXECUTE:
 195         script_execs.push_back(event);
 196         break;
 197       case TraceItem::TRACE_CHECK_HEADERS:
 198         check_headers.push_back(event);
 199         break;
 200       case TraceItem::TRACE_CHECK_HEADER:
 201         headers_checked++;
 202         break;
 203       case TraceItem::TRACE_SETUP:
 204       case TraceItem::TRACE_FILE_LOAD:
 205       case TraceItem::TRACE_FILE_WRITE:
 206       case TraceItem::TRACE_DEFINE_TARGET:
 207         break;  // Ignore these for the summary.
 208     }
 209   }
 210
 211   std::ostringstream out;
 212   SummarizeParses(parses, out);
 213   out << std::endl;
 214   SummarizeFileExecs(file_execs, out);
 215   out << std::endl;
 216   SummarizeScriptExecs(script_execs, out);
 217   out << std::endl;
 218
 219   // Generally there will only be one header check, but it's theoretically
 220   // possible for more than one to run if more than one build is going in
 221   // parallel. Just report the total of all of them.
 222   if (!check_headers.empty()) {
 223     double check_headers_time = 0;
 224     for (const auto& cur : check_headers)
 225       check_headers_time += cur->delta().InMillisecondsF();
 226
 227     out << "Header check time: (total time in ms, files checked)\n";
 228     out << base::StringPrintf(" %8.2f  %d\n",
 229                               check_headers_time, headers_checked);
 230   }
 231
 232   return out.str();
 233 }
 234
 235 void SaveTraces(const base::FilePath& file_name) {
 236   std::ostringstream out;
 237
 238   out << "{\"traceEvents\":[";
 239
 240   std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
 241
 242   // Write main thread metadata (assume this is being written on the main
 243   // thread).
 244   out << "{\"pid\":0,\"tid\":" << base::PlatformThread::CurrentId();
 245   out << ",\"ts\":0,\"ph\":\"M\",";
 246   out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
 247
 248   std::vector<TraceItem*> events = trace_log->events();
 249   for (size_t i = 0; i < events.size(); i++) {
 250     const TraceItem& item = *events[i];
 251
 252     if (i != 0)
 253       out << ",";
 254     out << "{\"pid\":0,\"tid\":" << item.thread_id();
 255     out << ",\"ts\":" << item.begin().ToInternalValue();
 256     out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
 257     out << ",\"dur\":" << item.delta().InMicroseconds();
 258
 259     quote_buffer.resize(0);
 260     base::EscapeJSONString(item.name(), true, &quote_buffer);
 261     out << ",\"name\":" << quote_buffer;
 262
 263     out << ",\"cat\":";
 264     switch (item.type()) {
 265       case TraceItem::TRACE_SETUP:
 266         out << "\"setup\"";
 267         break;
 268       case TraceItem::TRACE_FILE_LOAD:
 269         out << "\"load\"";
 270         break;
 271       case TraceItem::TRACE_FILE_PARSE:
 272         out << "\"parse\"";
 273         break;
 274       case TraceItem::TRACE_FILE_EXECUTE:
 275         out << "\"file_exec\"";
 276         break;
 277       case TraceItem::TRACE_FILE_WRITE:
 278         out << "\"file_write\"";
 279         break;
 280       case TraceItem::TRACE_SCRIPT_EXECUTE:
 281         out << "\"script_exec\"";
 282         break;
 283       case TraceItem::TRACE_DEFINE_TARGET:
 284         out << "\"define\"";
 285         break;
 286       case TraceItem::TRACE_CHECK_HEADER:
 287         out << "\"hdr\"";
 288         break;
 289       case TraceItem::TRACE_CHECK_HEADERS:
 290         out << "\"header_check\"";
 291         break;
 292     }
 293
 294     if (!item.toolchain().empty() || !item.cmdline().empty()) {
 295       out << ",\"args\":{";
 296       bool needs_comma = false;
 297       if (!item.toolchain().empty()) {
 298         quote_buffer.resize(0);
 299         base::EscapeJSONString(item.toolchain(), true, &quote_buffer);
 300         out << "\"toolchain\":" << quote_buffer;
 301         needs_comma = true;
 302       }
 303       if (!item.cmdline().empty()) {
 304         quote_buffer.resize(0);
 305         base::EscapeJSONString(item.cmdline(), true, &quote_buffer);
 306         if (needs_comma)
 307           out << ",";
 308         out << "\"cmdline\":" << quote_buffer;
 309         needs_comma = true;
 310       }
 311       out << "}";
 312     }
 313     out << "}";
 314   }
 315
 316   out << "]}";
 317
 318   std::string out_str = out.str();
 319   base::WriteFile(file_name, out_str.data(),
 320                        static_cast<int>(out_str.size()));
 321 }