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