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   ~TraceLog() {
     28     // Trace items leanked intentionally.
     29   }
     30 
     31   void Add(TraceItem* item) {
     32     base::AutoLock lock(lock_);
     33     events_.push_back(item);
     34   }
     35 
     36   // Returns a copy for threadsafety.
     37   std::vector<TraceItem*> events() const { return events_; }
     38 
     39  private:
     40   base::Lock lock_;
     41 
     42   std::vector<TraceItem*> events_;
     43 
     44   DISALLOW_COPY_AND_ASSIGN(TraceLog);
     45 };
     46 
     47 TraceLog* trace_log = NULL;
     48 
     49 struct Coalesced {
     50   Coalesced() : name_ptr(NULL), total_duration(0.0), count(0) {}
     51 
     52   const std::string* name_ptr;  // Pointer to a string with the name in it.
     53   double total_duration;
     54   int count;
     55 };
     56 
     57 bool DurationGreater(const TraceItem* a, const TraceItem* b) {
     58   return a->delta() > b->delta();
     59 }
     60 
     61 bool CoalescedDurationGreater(const Coalesced& a, const Coalesced& b) {
     62   return a.total_duration > b.total_duration;
     63 }
     64 
     65 void SummarizeParses(std::vector<const TraceItem*>& loads,
     66                      std::ostream& out) {
     67   out << "File parse times: (time in ms, name)\n";
     68 
     69   std::sort(loads.begin(), loads.end(), &DurationGreater);
     70 
     71   for (size_t i = 0; i < loads.size(); i++) {
     72     out << base::StringPrintf(" %8.2f  ",
     73                               loads[i]->delta().InMillisecondsF());
     74     out << loads[i]->name() << std::endl;
     75   }
     76 }
     77 
     78 void SummarizeCoalesced(std::vector<const TraceItem*>& items,
     79                         std::ostream& out) {
     80   // Group by file name.
     81   std::map<std::string, Coalesced> coalesced;
     82   for (size_t i = 0; i < items.size(); i++) {
     83     Coalesced& c = coalesced[items[i]->name()];
     84     c.name_ptr = &items[i]->name();
     85     c.total_duration += items[i]->delta().InMillisecondsF();
     86     c.count++;
     87   }
     88 
     89   // Sort by duration.
     90   std::vector<Coalesced> sorted;
     91   for (std::map<std::string, Coalesced>::iterator iter = coalesced.begin();
     92        iter != coalesced.end(); ++iter)
     93     sorted.push_back(iter->second);
     94   std::sort(sorted.begin(), sorted.end(), &CoalescedDurationGreater);
     95 
     96   for (size_t i = 0; i < sorted.size(); i++) {
     97     out << base::StringPrintf(" %8.2f  %d  ",
     98                               sorted[i].total_duration, sorted[i].count);
     99     out << *sorted[i].name_ptr << std::endl;
    100   }
    101 }
    102 
    103 void SummarizeFileExecs(std::vector<const TraceItem*>& execs,
    104                         std::ostream& out) {
    105   out << "File execute times: (total time in ms, # executions, name)\n";
    106   SummarizeCoalesced(execs, out);
    107 }
    108 
    109 void SummarizeScriptExecs(std::vector<const TraceItem*>& execs,
    110                           std::ostream& out) {
    111   out << "Script execute times: (total time in ms, # executions, name)\n";
    112   SummarizeCoalesced(execs, out);
    113 }
    114 
    115 }  // namespace
    116 
    117 TraceItem::TraceItem(Type type,
    118                      const std::string& name,
    119                      base::PlatformThreadId thread_id)
    120     : type_(type),
    121       name_(name),
    122       thread_id_(thread_id) {
    123 }
    124 
    125 TraceItem::~TraceItem() {
    126 }
    127 
    128 ScopedTrace::ScopedTrace(TraceItem::Type t, const std::string& name)
    129     : item_(NULL),
    130       done_(false) {
    131   if (trace_log) {
    132     item_ = new TraceItem(t, name, base::PlatformThread::CurrentId());
    133     item_->set_begin(base::TimeTicks::HighResNow());
    134   }
    135 }
    136 
    137 ScopedTrace::ScopedTrace(TraceItem::Type t, const Label& label)
    138     : item_(NULL),
    139       done_(false) {
    140   if (trace_log) {
    141     item_ = new TraceItem(t, label.GetUserVisibleName(false),
    142                           base::PlatformThread::CurrentId());
    143     item_->set_begin(base::TimeTicks::HighResNow());
    144   }
    145 }
    146 
    147 ScopedTrace::~ScopedTrace() {
    148   Done();
    149 }
    150 
    151 void ScopedTrace::SetToolchain(const Label& label) {
    152   if (item_)
    153     item_->set_toolchain(label.GetUserVisibleName(false));
    154 }
    155 
    156 void ScopedTrace::SetCommandLine(const CommandLine& cmdline) {
    157   if (item_)
    158     item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
    159 }
    160 
    161 void ScopedTrace::Done() {
    162   if (!done_) {
    163     done_ = true;
    164     if (trace_log) {
    165       item_->set_end(base::TimeTicks::HighResNow());
    166       AddTrace(item_);
    167     }
    168   }
    169 }
    170 
    171 void EnableTracing() {
    172   CHECK(!trace_log);
    173   trace_log = new TraceLog;
    174 }
    175 
    176 void AddTrace(TraceItem* item) {
    177   trace_log->Add(item);
    178 }
    179 
    180 std::string SummarizeTraces() {
    181   if (!trace_log)
    182     return std::string();
    183 
    184   std::vector<TraceItem*> events = trace_log->events();
    185 
    186   // Classify all events.
    187   std::vector<const TraceItem*> parses;
    188   std::vector<const TraceItem*> file_execs;
    189   std::vector<const TraceItem*> script_execs;
    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_FILE_LOAD:
    202       case TraceItem::TRACE_FILE_WRITE:
    203       case TraceItem::TRACE_DEFINE_TARGET:
    204         break;  // Ignore these for the summary.
    205     }
    206   }
    207 
    208   std::ostringstream out;
    209   SummarizeParses(parses, out);
    210   out << std::endl;
    211   SummarizeFileExecs(file_execs, out);
    212   out << std::endl;
    213   SummarizeScriptExecs(script_execs, out);
    214   out << std::endl;
    215 
    216   return out.str();
    217 }
    218 
    219 void SaveTraces(const base::FilePath& file_name) {
    220   std::ostringstream out;
    221 
    222   out << "{\"traceEvents\":[";
    223 
    224   std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
    225 
    226   // Write main thread metadata (assume this is being written on the main
    227   // thread).
    228   out << "{\"pid\":0,\"tid\":" << base::PlatformThread::CurrentId();
    229   out << ",\"ts\":0,\"ph\":\"M\",";
    230   out << "\"name\":\"thread_name\",\"args\":{\"name\":\"Main thread\"}},";
    231 
    232   std::vector<TraceItem*> events = trace_log->events();
    233   for (size_t i = 0; i < events.size(); i++) {
    234     const TraceItem& item = *events[i];
    235 
    236     if (i != 0)
    237       out << ",";
    238     out << "{\"pid\":0,\"tid\":" << item.thread_id();
    239     out << ",\"ts\":" << item.begin().ToInternalValue();
    240     out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
    241     out << ",\"dur\":" << item.delta().InMicroseconds();
    242 
    243     quote_buffer.resize(0);
    244     base::EscapeJSONString(item.name(), true, &quote_buffer);
    245     out << ",\"name\":" << quote_buffer;
    246 
    247     out << ",\"cat\":";
    248     switch (item.type()) {
    249       case TraceItem::TRACE_FILE_LOAD:
    250         out << "\"load\"";
    251         break;
    252       case TraceItem::TRACE_FILE_PARSE:
    253         out << "\"parse\"";
    254         break;
    255       case TraceItem::TRACE_FILE_EXECUTE:
    256         out << "\"file_exec\"";
    257         break;
    258       case TraceItem::TRACE_FILE_WRITE:
    259         out << "\"file_write\"";
    260         break;
    261       case TraceItem::TRACE_SCRIPT_EXECUTE:
    262         out << "\"script_exec\"";
    263         break;
    264       case TraceItem::TRACE_DEFINE_TARGET:
    265         out << "\"define\"";
    266     }
    267 
    268     if (!item.toolchain().empty() || !item.cmdline().empty()) {
    269       out << ",\"args\":{";
    270       bool needs_comma = false;
    271       if (!item.toolchain().empty()) {
    272         quote_buffer.resize(0);
    273         base::EscapeJSONString(item.toolchain(), true, &quote_buffer);
    274         out << "\"toolchain\":" << quote_buffer;
    275         needs_comma = true;
    276       }
    277       if (!item.cmdline().empty()) {
    278         quote_buffer.resize(0);
    279         base::EscapeJSONString(item.cmdline(), true, &quote_buffer);
    280         if (needs_comma)
    281           out << ",";
    282         out << "\"cmdline\":" << quote_buffer;
    283         needs_comma = true;
    284       }
    285       out << "}";
    286     }
    287     out << "}";
    288   }
    289 
    290   out << "]}";
    291 
    292   std::string out_str = out.str();
    293   file_util::WriteFile(file_name, out_str.data(),
    294                        static_cast<int>(out_str.size()));
    295 }
    296