base/trace_event/trace_event_impl.cc

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