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