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