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   cached_memory_overhead_estimate_.reset();
 175 }
 176
 177 void TraceEvent::UpdateDuration(const TraceTicks& now,
 178                                 const ThreadTicks& thread_now) {
 179   DCHECK_EQ(duration_.ToInternalValue(), -1);
 180   duration_ = now - timestamp_;
 181   thread_duration_ = thread_now - thread_timestamp_;
 182 }
 183
 184 void TraceEvent::EstimateTraceMemoryOverhead(
 185     TraceEventMemoryOverhead* overhead) {
 186   if (!cached_memory_overhead_estimate_) {
 187     cached_memory_overhead_estimate_.reset(new TraceEventMemoryOverhead);
 188     cached_memory_overhead_estimate_->Add("TraceEvent", sizeof(*this));
 189     // TODO(primiano): parameter_copy_storage_ is refcounted and, in theory,
 190     // could be shared by several events and we might overcount. In practice
 191     // this is unlikely but it's worth checking.
 192     if (parameter_copy_storage_) {
 193       cached_memory_overhead_estimate_->AddRefCountedString(
 194           *parameter_copy_storage_.get());
 195     }
 196     for (size_t i = 0; i < kTraceMaxNumArgs; ++i) {
 197       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
 198         convertable_values_[i]->EstimateTraceMemoryOverhead(
 199             cached_memory_overhead_estimate_.get());
 200       }
 201     }
 202     cached_memory_overhead_estimate_->AddSelf();
 203   }
 204   overhead->Update(*cached_memory_overhead_estimate_);
 205 }
 206
 207 // static
 208 void TraceEvent::AppendValueAsJSON(unsigned char type,
 209                                    TraceEvent::TraceValue value,
 210                                    std::string* out) {
 211   switch (type) {
 212     case TRACE_VALUE_TYPE_BOOL:
 213       *out += value.as_bool ? "true" : "false";
 214       break;
 215     case TRACE_VALUE_TYPE_UINT:
 216       StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
 217       break;
 218     case TRACE_VALUE_TYPE_INT:
 219       StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
 220       break;
 221     case TRACE_VALUE_TYPE_DOUBLE: {
 222       // FIXME: base/json/json_writer.cc is using the same code,
 223       //        should be made into a common method.
 224       std::string real;
 225       double val = value.as_double;
 226       if (std::isfinite(val)) {
 227         real = DoubleToString(val);
 228         // Ensure that the number has a .0 if there's no decimal or 'e'.  This
 229         // makes sure that when we read the JSON back, it's interpreted as a
 230         // real rather than an int.
 231         if (real.find('.') == std::string::npos &&
 232             real.find('e') == std::string::npos &&
 233             real.find('E') == std::string::npos) {
 234           real.append(".0");
 235         }
 236         // The JSON spec requires that non-integer values in the range (-1,1)
 237         // have a zero before the decimal point - ".52" is not valid, "0.52" is.
 238         if (real[0] == '.') {
 239           real.insert(0, "0");
 240         } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
 241           // "-.1" bad "-0.1" good
 242           real.insert(1, "0");
 243         }
 244       } else if (std::isnan(val)){
 245         // The JSON spec doesn't allow NaN and Infinity (since these are
 246         // objects in EcmaScript).  Use strings instead.
 247         real = "\"NaN\"";
 248       } else if (val < 0) {
 249         real = "\"-Infinity\"";
 250       } else {
 251         real = "\"Infinity\"";
 252       }
 253       StringAppendF(out, "%s", real.c_str());
 254       break;
 255     }
 256     case TRACE_VALUE_TYPE_POINTER:
 257       // JSON only supports double and int numbers.
 258       // So as not to lose bits from a 64-bit pointer, output as a hex string.
 259       StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast<uint64>(
 260                                      reinterpret_cast<intptr_t>(
 261                                      value.as_pointer)));
 262       break;
 263     case TRACE_VALUE_TYPE_STRING:
 264     case TRACE_VALUE_TYPE_COPY_STRING:
 265       EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
 266       break;
 267     default:
 268       NOTREACHED() << "Don't know how to print this value";
 269       break;
 270   }
 271 }
 272
 273 void TraceEvent::AppendAsJSON(
 274     std::string* out,
 275     const ArgumentFilterPredicate& argument_filter_predicate) const {
 276   int64 time_int64 = timestamp_.ToInternalValue();
 277   int process_id = TraceLog::GetInstance()->process_id();
 278   const char* category_group_name =
 279       TraceLog::GetCategoryGroupName(category_group_enabled_);
 280
 281   // Category group checked at category creation time.
 282   DCHECK(!strchr(name_, '"'));
 283   StringAppendF(out, "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64
 284                      ","
 285                      "\"ph\":\"%c\",\"cat\":\"%s\",\"name\":\"%s\",\"args\":",
 286                 process_id, thread_id_, time_int64, phase_, category_group_name,
 287                 name_);
 288
 289   // Output argument names and values, stop at first NULL argument name.
 290   bool strip_args = arg_names_[0] && !argument_filter_predicate.is_null() &&
 291                     !argument_filter_predicate.Run(category_group_name, name_);
 292
 293   if (strip_args) {
 294     *out += "\"__stripped__\"";
 295   } else {
 296     *out += "{";
 297
 298     for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
 299       if (i > 0)
 300         *out += ",";
 301       *out += "\"";
 302       *out += arg_names_[i];
 303       *out += "\":";
 304
 305       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 306         convertable_values_[i]->AppendAsTraceFormat(out);
 307       else
 308         AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
 309     }
 310
 311     *out += "}";
 312   }
 313
 314   if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
 315     int64 duration = duration_.ToInternalValue();
 316     if (duration != -1)
 317       StringAppendF(out, ",\"dur\":%" PRId64, duration);
 318     if (!thread_timestamp_.is_null()) {
 319       int64 thread_duration = thread_duration_.ToInternalValue();
 320       if (thread_duration != -1)
 321         StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
 322     }
 323   }
 324
 325   // Output tts if thread_timestamp is valid.
 326   if (!thread_timestamp_.is_null()) {
 327     int64 thread_time_int64 = thread_timestamp_.ToInternalValue();
 328     StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
 329   }
 330
 331   // Output async tts marker field if flag is set.
 332   if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
 333     StringAppendF(out, ", \"use_async_tts\":1");
 334   }
 335
 336   // If id_ is set, print it out as a hex string so we don't loose any
 337   // bits (it might be a 64-bit pointer).
 338   if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
 339     StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
 340
 341   if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
 342     StringAppendF(out, ",\"bp\":\"e\"");
 343
 344   if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) ||
 345       (flags_ & TRACE_EVENT_FLAG_FLOW_IN)) {
 346     StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"",
 347                   static_cast<uint64>(bind_id_));
 348   }
 349   if (flags_ & TRACE_EVENT_FLAG_FLOW_IN)
 350     StringAppendF(out, ",\"flow_in\":true");
 351   if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT)
 352     StringAppendF(out, ",\"flow_out\":true");
 353
 354   // Similar to id_, print the context_id as hex if present.
 355   if (flags_ & TRACE_EVENT_FLAG_HAS_CONTEXT_ID)
 356     StringAppendF(out, ",\"cid\":\"0x%" PRIx64 "\"",
 357                   static_cast<uint64>(context_id_));
 358
 359   // Instant events also output their scope.
 360   if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
 361     char scope = '?';
 362     switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
 363       case TRACE_EVENT_SCOPE_GLOBAL:
 364         scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
 365         break;
 366
 367       case TRACE_EVENT_SCOPE_PROCESS:
 368         scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
 369         break;
 370
 371       case TRACE_EVENT_SCOPE_THREAD:
 372         scope = TRACE_EVENT_SCOPE_NAME_THREAD;
 373         break;
 374     }
 375     StringAppendF(out, ",\"s\":\"%c\"", scope);
 376   }
 377
 378   *out += "}";
 379 }
 380
 381 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
 382   *out << name_ << "[";
 383   *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
 384   *out << "]";
 385   if (arg_names_[0]) {
 386     *out << ", {";
 387     for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
 388       if (i > 0)
 389         *out << ", ";
 390       *out << arg_names_[i] << ":";
 391       std::string value_as_text;
 392
 393       if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
 394         convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
 395       else
 396         AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);
 397
 398       *out << value_as_text;
 399     }
 400     *out << "}";
 401   }
 402 }
 403
 404 }  // namespace trace_event
 405 }  // namespace base