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   CHECK(!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_FILE_LOAD:
 208       case TraceItem::TRACE_FILE_WRITE:
 209       case TraceItem::TRACE_DEFINE_TARGET:
 210         break;  // Ignore these for the summary.
 211     }
 212   }
 213
 214   std::ostringstream out;
 215   SummarizeParses(parses, out);
 216   out << std::endl;
 217   SummarizeFileExecs(file_execs, out);
 218   out << std::endl;
 219   SummarizeScriptExecs(script_execs, out);
 220   out << std::endl;
 221
 222   // Generally there will only be one header check, but it's theoretically
 223   // possible for more than one to run if more than one build is going in
 224   // parallel. Just report the total of all of them.
 225   if (!check_headers.empty()) {
 226     float check_headers_time = 0;
 227     for (size_t i = 0; i < check_headers.size(); i++)
 228       check_headers_time += check_headers[i]->delta().InMillisecondsF();
 229
 230     out << "Header check time: (total time in ms, files checked)\n";
 231     out << base::StringPrintf(" %8.2f  %d\n",
 232                               check_headers_time, headers_checked);
 233   }
 234
 235   return out.str();
 236 }
 237
 238 void SaveTraces(const base::FilePath& file_name) {
 239   std::ostringstream out;
 240
 241   out << "{\"traceEvents\":[";
 242
 243   std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
 244
 245   // Write main thread metadata (assume this is being written on the main
 246   // thread).
 247   out << "{\"pid\":0,\"tid\":" << base::PlatformThread::CurrentId();
 248   out << ",\"ts\":0,\"ph\":\"M\",";
 249   out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
 250
 251   std::vector<TraceItem*> events = trace_log->events();
 252   for (size_t i = 0; i < events.size(); i++) {
 253     const TraceItem& item = *events[i];
 254
 255     if (i != 0)
 256       out << ",";
 257     out << "{\"pid\":0,\"tid\":" << item.thread_id();
 258     out << ",\"ts\":" << item.begin().ToInternalValue();
 259     out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
 260     out << ",\"dur\":" << item.delta().InMicroseconds();
 261
 262     quote_buffer.resize(0);
 263     base::EscapeJSONString(item.name(), true, &quote_buffer);
 264     out << ",\"name\":" << quote_buffer;
 265
 266     out << ",\"cat\":";
 267     switch (item.type()) {
 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 }