Home | History | Annotate | Download | only in gn 
      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 }
    326