Home | History | Annotate | Download | only in trace_event 
      1 // Copyright (c) 2012 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 "base/trace_event/trace_event_impl.h"
      6 
      7 #include <stddef.h>
      8 
      9 #include "base/format_macros.h"
     10 #include "base/json/string_escape.h"
     11 #include "base/process/process_handle.h"
     12 #include "base/stl_util.h"
     13 #include "base/strings/string_number_conversions.h"
     14 #include "base/strings/string_util.h"
     15 #include "base/strings/stringprintf.h"
     16 #include "base/strings/utf_string_conversions.h"
     17 #include "base/trace_event/trace_event.h"
     18 #include "base/trace_event/trace_log.h"
     19 
     20 namespace base {
     21 namespace trace_event {
     22 
     23 namespace {
     24 
     25 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
     26 
     27 // Copies |*member| into |*buffer|, sets |*member| to point to this new
     28 // location, and then advances |*buffer| by the amount written.
     29 void CopyTraceEventParameter(char** buffer,
     30                              const char** member,
     31                              const char* end) {
     32   if (*member) {
     33     size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
     34     DCHECK_LE(static_cast<int>(written), end - *buffer);
     35     *member = *buffer;
     36     *buffer += written;
     37   }
     38 }
     39 
     40 }  // namespace
     41 
     42 TraceEvent::TraceEvent()
     43     : duration_(TimeDelta::FromInternalValue(-1)),
     44       scope_(trace_event_internal::kGlobalScope),
     45       id_(0u),
     46       category_group_enabled_(NULL),
     47       name_(NULL),
     48       thread_id_(0),
     49       flags_(0),
     50       phase_(TRACE_EVENT_PHASE_BEGIN) {
     51   for (int i = 0; i < kTraceMaxNumArgs; ++i)
     52     arg_names_[i] = NULL;
     53   memset(arg_values_, 0, sizeof(arg_values_));
     54 }
     55 
     56 TraceEvent::~TraceEvent() {
     57 }
     58 
     59 void TraceEvent::MoveFrom(std::unique_ptr<TraceEvent> other) {
     60   timestamp_ = other->timestamp_;
     61   thread_timestamp_ = other->thread_timestamp_;
     62   duration_ = other->duration_;
     63   scope_ = other->scope_;
     64   id_ = other->id_;
     65   category_group_enabled_ = other->category_group_enabled_;
     66   name_ = other->name_;
     67   if (other->flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID)
     68     process_id_ = other->process_id_;
     69   else
     70     thread_id_ = other->thread_id_;
     71   phase_ = other->phase_;
     72   flags_ = other->flags_;
     73   parameter_copy_storage_ = std::move(other->parameter_copy_storage_);
     74 
     75   for (int i = 0; i < kTraceMaxNumArgs; ++i) {
     76     arg_names_[i] = other->arg_names_[i];
     77     arg_types_[i] = other->arg_types_[i];
     78     arg_values_[i] = other->arg_values_[i];
     79     convertable_values_[i] = std::move(other->convertable_values_[i]);
     80   }
     81 }
     82 
     83 void TraceEvent::Initialize(
     84     int thread_id,
     85     TimeTicks timestamp,
     86     ThreadTicks thread_timestamp,
     87     char phase,
     88     const unsigned char* category_group_enabled,
     89     const char* name,
     90     const char* scope,
     91     unsigned long long id,
     92     unsigned long long bind_id,
     93     int num_args,
     94     const char** arg_names,
     95     const unsigned char* arg_types,
     96     const unsigned long long* arg_values,
     97     std::unique_ptr<ConvertableToTraceFormat>* convertable_values,
     98     unsigned int flags) {
     99   timestamp_ = timestamp;
    100   thread_timestamp_ = thread_timestamp;
    101   duration_ = TimeDelta::FromInternalValue(-1);
    102   scope_ = scope;
    103   id_ = id;
    104   category_group_enabled_ = category_group_enabled;
    105   name_ = name;
    106   thread_id_ = thread_id;
    107   phase_ = phase;
    108   flags_ = flags;
    109   bind_id_ = bind_id;
    110 
    111   // Clamp num_args since it may have been set by a third_party library.
    112   num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
    113   int i = 0;
    114   for (; i < num_args; ++i) {
    115     arg_names_[i] = arg_names[i];
    116     arg_types_[i] = arg_types[i];
    117 
    118     if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
    119       convertable_values_[i] = std::move(convertable_values[i]);
    120     } else {
    121       arg_values_[i].as_uint = arg_values[i];
    122       convertable_values_[i].reset();
    123     }
    124   }
    125   for (; i < kTraceMaxNumArgs; ++i) {
    126     arg_names_[i] = NULL;
    127     arg_values_[i].as_uint = 0u;
    128     convertable_values_[i].reset();
    129     arg_types_[i] = TRACE_VALUE_TYPE_UINT;
    130   }
    131 
    132   bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
    133   size_t alloc_size = 0;
    134   if (copy) {
    135     alloc_size += GetAllocLength(name) + GetAllocLength(scope);
    136     for (i = 0; i < num_args; ++i) {
    137       alloc_size += GetAllocLength(arg_names_[i]);
    138       if (arg_types_[i] == TRACE_VALUE_TYPE_STRING)
    139         arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING;
    140     }
    141   }
    142 
    143   bool arg_is_copy[kTraceMaxNumArgs];
    144   for (i = 0; i < num_args; ++i) {
    145     // No copying of convertable types, we retain ownership.
    146     if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
    147       continue;
    148 
    149     // We only take a copy of arg_vals if they are of type COPY_STRING.
    150     arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
    151     if (arg_is_copy[i])
    152       alloc_size += GetAllocLength(arg_values_[i].as_string);
    153   }
    154 
    155   if (alloc_size) {
    156     parameter_copy_storage_.reset(new std::string);
    157     parameter_copy_storage_->resize(alloc_size);
    158     char* ptr = string_as_array(parameter_copy_storage_.get());
    159     const char* end = ptr + alloc_size;
    160     if (copy) {
    161       CopyTraceEventParameter(&ptr, &name_, end);
    162       CopyTraceEventParameter(&ptr, &scope_, end);
    163       for (i = 0; i < num_args; ++i) {
    164         CopyTraceEventParameter(&ptr, &arg_names_[i], end);
    165       }
    166     }
    167     for (i = 0; i < num_args; ++i) {
    168       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
    169         continue;
    170       if (arg_is_copy[i])
    171         CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
    172     }
    173     DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
    174   }
    175 }
    176 
    177 void TraceEvent::Reset() {
    178   // Only reset fields that won't be initialized in Initialize(), or that may
    179   // hold references to other objects.
    180   duration_ = TimeDelta::FromInternalValue(-1);
    181   parameter_copy_storage_.reset();
    182   for (int i = 0; i < kTraceMaxNumArgs; ++i)
    183     convertable_values_[i].reset();
    184 }
    185 
    186 void TraceEvent::UpdateDuration(const TimeTicks& now,
    187                                 const ThreadTicks& thread_now) {
    188   DCHECK_EQ(duration_.ToInternalValue(), -1);
    189   duration_ = now - timestamp_;
    190 
    191   // |thread_timestamp_| can be empty if the thread ticks clock wasn't
    192   // initialized when it was recorded.
    193   if (thread_timestamp_ != ThreadTicks())
    194     thread_duration_ = thread_now - thread_timestamp_;
    195 }
    196 
    197 void TraceEvent::EstimateTraceMemoryOverhead(
    198     TraceEventMemoryOverhead* overhead) {
    199   overhead->Add("TraceEvent", sizeof(*this));
    200 
    201   if (parameter_copy_storage_)
    202     overhead->AddString(*parameter_copy_storage_);
    203 
    204   for (size_t i = 0; i < kTraceMaxNumArgs; ++i) {
    205     if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
    206       convertable_values_[i]->EstimateTraceMemoryOverhead(overhead);
    207   }
    208 }
    209 
    210 // static
    211 void TraceEvent::AppendValueAsJSON(unsigned char type,
    212                                    TraceEvent::TraceValue value,
    213                                    std::string* out) {
    214   switch (type) {
    215     case TRACE_VALUE_TYPE_BOOL:
    216       *out += value.as_bool ? "true" : "false";
    217       break;
    218     case TRACE_VALUE_TYPE_UINT:
    219       StringAppendF(out, "%" PRIu64, static_cast<uint64_t>(value.as_uint));
    220       break;
    221     case TRACE_VALUE_TYPE_INT:
    222       StringAppendF(out, "%" PRId64, static_cast<int64_t>(value.as_int));
    223       break;
    224     case TRACE_VALUE_TYPE_DOUBLE: {
    225       // FIXME: base/json/json_writer.cc is using the same code,
    226       //        should be made into a common method.
    227       std::string real;
    228       double val = value.as_double;
    229       if (std::isfinite(val)) {
    230         real = DoubleToString(val);
    231         // Ensure that the number has a .0 if there's no decimal or 'e'.  This
    232         // makes sure that when we read the JSON back, it's interpreted as a
    233         // real rather than an int.
    234         if (real.find('.') == std::string::npos &&
    235             real.find('e') == std::string::npos &&
    236             real.find('E') == std::string::npos) {
    237           real.append(".0");
    238         }
    239         // The JSON spec requires that non-integer values in the range (-1,1)
    240         // have a zero before the decimal point - ".52" is not valid, "0.52" is.
    241         if (real[0] == '.') {
    242           real.insert(0, "0");
    243         } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
    244           // "-.1" bad "-0.1" good
    245           real.insert(1, "0");
    246         }
    247       } else if (std::isnan(val)){
    248         // The JSON spec doesn't allow NaN and Infinity (since these are
    249         // objects in EcmaScript).  Use strings instead.
    250         real = "\"NaN\"";
    251       } else if (val < 0) {
    252         real = "\"-Infinity\"";
    253       } else {
    254         real = "\"Infinity\"";
    255       }
    256       StringAppendF(out, "%s", real.c_str());
    257       break;
    258     }
    259     case TRACE_VALUE_TYPE_POINTER:
    260       // JSON only supports double and int numbers.
    261       // So as not to lose bits from a 64-bit pointer, output as a hex string.
    262       StringAppendF(
    263           out, "\"0x%" PRIx64 "\"",
    264           static_cast<uint64_t>(reinterpret_cast<uintptr_t>(value.as_pointer)));
    265       break;
    266     case TRACE_VALUE_TYPE_STRING:
    267     case TRACE_VALUE_TYPE_COPY_STRING:
    268       EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
    269       break;
    270     default:
    271       NOTREACHED() << "Don't know how to print this value";
    272       break;
    273   }
    274 }
    275 
    276 void TraceEvent::AppendAsJSON(
    277     std::string* out,
    278     const ArgumentFilterPredicate& argument_filter_predicate) const {
    279   int64_t time_int64 = timestamp_.ToInternalValue();
    280   int process_id;
    281   int thread_id;
    282   if ((flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) &&
    283       process_id_ != kNullProcessId) {
    284     process_id = process_id_;
    285     thread_id = -1;
    286   } else {
    287     process_id = TraceLog::GetInstance()->process_id();
    288     thread_id = thread_id_;
    289   }
    290   const char* category_group_name =
    291       TraceLog::GetCategoryGroupName(category_group_enabled_);
    292 
    293   // Category group checked at category creation time.
    294   DCHECK(!strchr(name_, '"'));
    295   StringAppendF(out, "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64
    296                      ",\"ph\":\"%c\",\"cat\":\"%s\",\"name\":",
    297                 process_id, thread_id, time_int64, phase_, category_group_name);
    298   EscapeJSONString(name_, true, out);
    299   *out += ",\"args\":";
    300 
    301   // Output argument names and values, stop at first NULL argument name.
    302   // TODO(oysteine): The dual predicates here is a bit ugly; if the filtering
    303   // capabilities need to grow even more precise we should rethink this
    304   // approach
    305   ArgumentNameFilterPredicate argument_name_filter_predicate;
    306   bool strip_args =
    307       arg_names_[0] && !argument_filter_predicate.is_null() &&
    308       !argument_filter_predicate.Run(category_group_name, name_,
    309                                      &argument_name_filter_predicate);
    310 
    311   if (strip_args) {
    312     *out += "\"__stripped__\"";
    313   } else {
    314     *out += "{";
    315 
    316     for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
    317       if (i > 0)
    318         *out += ",";
    319       *out += "\"";
    320       *out += arg_names_[i];
    321       *out += "\":";
    322 
    323       if (argument_name_filter_predicate.is_null() ||
    324           argument_name_filter_predicate.Run(arg_names_[i])) {
    325         if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
    326           convertable_values_[i]->AppendAsTraceFormat(out);
    327         else
    328           AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
    329       } else {
    330         *out += "\"__stripped__\"";
    331       }
    332     }
    333 
    334     *out += "}";
    335   }
    336 
    337   if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
    338     int64_t duration = duration_.ToInternalValue();
    339     if (duration != -1)
    340       StringAppendF(out, ",\"dur\":%" PRId64, duration);
    341     if (!thread_timestamp_.is_null()) {
    342       int64_t thread_duration = thread_duration_.ToInternalValue();
    343       if (thread_duration != -1)
    344         StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
    345     }
    346   }
    347 
    348   // Output tts if thread_timestamp is valid.
    349   if (!thread_timestamp_.is_null()) {
    350     int64_t thread_time_int64 = thread_timestamp_.ToInternalValue();
    351     StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
    352   }
    353 
    354   // Output async tts marker field if flag is set.
    355   if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
    356     StringAppendF(out, ", \"use_async_tts\":1");
    357   }
    358 
    359   // If id_ is set, print it out as a hex string so we don't loose any
    360   // bits (it might be a 64-bit pointer).
    361   if (flags_ & TRACE_EVENT_FLAG_HAS_ID) {
    362     if (scope_ != trace_event_internal::kGlobalScope)
    363       StringAppendF(out, ",\"scope\":\"%s\"", scope_);
    364     StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64_t>(id_));
    365   }
    366 
    367   if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
    368     StringAppendF(out, ",\"bp\":\"e\"");
    369 
    370   if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) ||
    371       (flags_ & TRACE_EVENT_FLAG_FLOW_IN)) {
    372     StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"",
    373                   static_cast<uint64_t>(bind_id_));
    374   }
    375   if (flags_ & TRACE_EVENT_FLAG_FLOW_IN)
    376     StringAppendF(out, ",\"flow_in\":true");
    377   if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT)
    378     StringAppendF(out, ",\"flow_out\":true");
    379 
    380   // Instant events also output their scope.
    381   if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
    382     char scope = '?';
    383     switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
    384       case TRACE_EVENT_SCOPE_GLOBAL:
    385         scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
    386         break;
    387 
    388       case TRACE_EVENT_SCOPE_PROCESS:
    389         scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
    390         break;
    391 
    392       case TRACE_EVENT_SCOPE_THREAD:
    393         scope = TRACE_EVENT_SCOPE_NAME_THREAD;
    394         break;
    395     }
    396     StringAppendF(out, ",\"s\":\"%c\"", scope);
    397   }
    398 
    399   *out += "}";
    400 }
    401 
    402 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
    403   *out << name_ << "[";
    404   *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
    405   *out << "]";
    406   if (arg_names_[0]) {
    407     *out << ", {";
    408     for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
    409       if (i > 0)
    410         *out << ", ";
    411       *out << arg_names_[i] << ":";
    412       std::string value_as_text;
    413 
    414       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
    415         convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
    416       else
    417         AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);
    418 
    419       *out << value_as_text;
    420     }
    421     *out << "}";
    422   }
    423 }
    424 
    425 }  // namespace trace_event
    426 }  // namespace base
    427