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