// Copyright (c) 2012 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "base/trace_event/trace_event_impl.h" #include "base/format_macros.h" #include "base/json/string_escape.h" #include "base/process/process_handle.h" #include "base/stl_util.h" #include "base/strings/string_number_conversions.h" #include "base/strings/string_util.h" #include "base/strings/stringprintf.h" #include "base/strings/utf_string_conversions.h" #include "base/trace_event/trace_event.h" #include "base/trace_event/trace_log.h" namespace base { namespace trace_event { namespace { size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; } // Copies |*member| into |*buffer|, sets |*member| to point to this new // location, and then advances |*buffer| by the amount written. void CopyTraceEventParameter(char** buffer, const char** member, const char* end) { if (*member) { size_t written = strlcpy(*buffer, *member, end - *buffer) + 1; DCHECK_LE(static_cast(written), end - *buffer); *member = *buffer; *buffer += written; } } } // namespace TraceEvent::TraceEvent() : duration_(TimeDelta::FromInternalValue(-1)), id_(0u), category_group_enabled_(NULL), name_(NULL), thread_id_(0), flags_(0), phase_(TRACE_EVENT_PHASE_BEGIN) { for (int i = 0; i < kTraceMaxNumArgs; ++i) arg_names_[i] = NULL; memset(arg_values_, 0, sizeof(arg_values_)); } TraceEvent::~TraceEvent() { } void TraceEvent::CopyFrom(const TraceEvent& other) { timestamp_ = other.timestamp_; thread_timestamp_ = other.thread_timestamp_; duration_ = other.duration_; id_ = other.id_; context_id_ = other.context_id_; category_group_enabled_ = other.category_group_enabled_; name_ = other.name_; if (other.flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) process_id_ = other.process_id_; else thread_id_ = other.thread_id_; phase_ = other.phase_; flags_ = other.flags_; parameter_copy_storage_ = other.parameter_copy_storage_; for (int i = 0; i < kTraceMaxNumArgs; ++i) { arg_names_[i] = other.arg_names_[i]; arg_types_[i] = other.arg_types_[i]; arg_values_[i] = other.arg_values_[i]; convertable_values_[i] = other.convertable_values_[i]; } } void TraceEvent::Initialize( int thread_id, TimeTicks timestamp, ThreadTicks thread_timestamp, char phase, const unsigned char* category_group_enabled, const char* name, unsigned long long id, unsigned long long context_id, unsigned long long bind_id, int num_args, const char** arg_names, const unsigned char* arg_types, const unsigned long long* arg_values, const scoped_refptr* convertable_values, unsigned int flags) { timestamp_ = timestamp; thread_timestamp_ = thread_timestamp; duration_ = TimeDelta::FromInternalValue(-1); id_ = id; context_id_ = context_id; category_group_enabled_ = category_group_enabled; name_ = name; thread_id_ = thread_id; phase_ = phase; flags_ = flags; bind_id_ = bind_id; // Clamp num_args since it may have been set by a third_party library. num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args; int i = 0; for (; i < num_args; ++i) { arg_names_[i] = arg_names[i]; arg_types_[i] = arg_types[i]; if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) convertable_values_[i] = convertable_values[i]; else arg_values_[i].as_uint = arg_values[i]; } for (; i < kTraceMaxNumArgs; ++i) { arg_names_[i] = NULL; arg_values_[i].as_uint = 0u; convertable_values_[i] = NULL; arg_types_[i] = TRACE_VALUE_TYPE_UINT; } bool copy = !!(flags & TRACE_EVENT_FLAG_COPY); size_t alloc_size = 0; if (copy) { alloc_size += GetAllocLength(name); for (i = 0; i < num_args; ++i) { alloc_size += GetAllocLength(arg_names_[i]); if (arg_types_[i] == TRACE_VALUE_TYPE_STRING) arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING; } } bool arg_is_copy[kTraceMaxNumArgs]; for (i = 0; i < num_args; ++i) { // No copying of convertable types, we retain ownership. if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) continue; // We only take a copy of arg_vals if they are of type COPY_STRING. arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING); if (arg_is_copy[i]) alloc_size += GetAllocLength(arg_values_[i].as_string); } if (alloc_size) { parameter_copy_storage_ = new RefCountedString; parameter_copy_storage_->data().resize(alloc_size); char* ptr = string_as_array(¶meter_copy_storage_->data()); const char* end = ptr + alloc_size; if (copy) { CopyTraceEventParameter(&ptr, &name_, end); for (i = 0; i < num_args; ++i) { CopyTraceEventParameter(&ptr, &arg_names_[i], end); } } for (i = 0; i < num_args; ++i) { if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) continue; if (arg_is_copy[i]) CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end); } DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end; } } void TraceEvent::Reset() { // Only reset fields that won't be initialized in Initialize(), or that may // hold references to other objects. duration_ = TimeDelta::FromInternalValue(-1); parameter_copy_storage_ = NULL; for (int i = 0; i < kTraceMaxNumArgs; ++i) convertable_values_[i] = NULL; } void TraceEvent::UpdateDuration(const TimeTicks& now, const ThreadTicks& thread_now) { DCHECK_EQ(duration_.ToInternalValue(), -1); duration_ = now - timestamp_; // |thread_timestamp_| can be empty if the thread ticks clock wasn't // initialized when it was recorded. if (thread_timestamp_ != ThreadTicks()) thread_duration_ = thread_now - thread_timestamp_; } void TraceEvent::EstimateTraceMemoryOverhead( TraceEventMemoryOverhead* overhead) { overhead->Add("TraceEvent", sizeof(*this)); // TODO(primiano): parameter_copy_storage_ is refcounted and, in theory, // could be shared by several events and we might overcount. In practice // this is unlikely but it's worth checking. if (parameter_copy_storage_) overhead->AddRefCountedString(*parameter_copy_storage_.get()); for (size_t i = 0; i < kTraceMaxNumArgs; ++i) { if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) convertable_values_[i]->EstimateTraceMemoryOverhead(overhead); } } // static void TraceEvent::AppendValueAsJSON(unsigned char type, TraceEvent::TraceValue value, std::string* out) { switch (type) { case TRACE_VALUE_TYPE_BOOL: *out += value.as_bool ? "true" : "false"; break; case TRACE_VALUE_TYPE_UINT: StringAppendF(out, "%" PRIu64, static_cast(value.as_uint)); break; case TRACE_VALUE_TYPE_INT: StringAppendF(out, "%" PRId64, static_cast(value.as_int)); break; case TRACE_VALUE_TYPE_DOUBLE: { // FIXME: base/json/json_writer.cc is using the same code, // should be made into a common method. std::string real; double val = value.as_double; if (std::isfinite(val)) { real = DoubleToString(val); // Ensure that the number has a .0 if there's no decimal or 'e'. This // makes sure that when we read the JSON back, it's interpreted as a // real rather than an int. if (real.find('.') == std::string::npos && real.find('e') == std::string::npos && real.find('E') == std::string::npos) { real.append(".0"); } // The JSON spec requires that non-integer values in the range (-1,1) // have a zero before the decimal point - ".52" is not valid, "0.52" is. if (real[0] == '.') { real.insert(0, "0"); } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') { // "-.1" bad "-0.1" good real.insert(1, "0"); } } else if (std::isnan(val)){ // The JSON spec doesn't allow NaN and Infinity (since these are // objects in EcmaScript). Use strings instead. real = "\"NaN\""; } else if (val < 0) { real = "\"-Infinity\""; } else { real = "\"Infinity\""; } StringAppendF(out, "%s", real.c_str()); break; } case TRACE_VALUE_TYPE_POINTER: // JSON only supports double and int numbers. // So as not to lose bits from a 64-bit pointer, output as a hex string. StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast( reinterpret_cast( value.as_pointer))); break; case TRACE_VALUE_TYPE_STRING: case TRACE_VALUE_TYPE_COPY_STRING: EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out); break; default: NOTREACHED() << "Don't know how to print this value"; break; } } void TraceEvent::AppendAsJSON( std::string* out, const ArgumentFilterPredicate& argument_filter_predicate) const { int64 time_int64 = timestamp_.ToInternalValue(); int process_id; int thread_id; if ((flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) && process_id_ != kNullProcessId) { process_id = process_id_; thread_id = -1; } else { process_id = TraceLog::GetInstance()->process_id(); thread_id = thread_id_; } const char* category_group_name = TraceLog::GetCategoryGroupName(category_group_enabled_); // Category group checked at category creation time. DCHECK(!strchr(name_, '"')); StringAppendF(out, "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 "," "\"ph\":\"%c\",\"cat\":\"%s\",\"name\":\"%s\",\"args\":", process_id, thread_id, time_int64, phase_, category_group_name, name_); // Output argument names and values, stop at first NULL argument name. // TODO(oysteine): The dual predicates here is a bit ugly; if the filtering // capabilities need to grow even more precise we should rethink this // approach ArgumentNameFilterPredicate argument_name_filter_predicate; bool strip_args = arg_names_[0] && !argument_filter_predicate.is_null() && !argument_filter_predicate.Run(category_group_name, name_, &argument_name_filter_predicate); if (strip_args) { *out += "\"__stripped__\""; } else { *out += "{"; for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) { if (i > 0) *out += ","; *out += "\""; *out += arg_names_[i]; *out += "\":"; if (argument_name_filter_predicate.is_null() || argument_name_filter_predicate.Run(arg_names_[i])) { if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) convertable_values_[i]->AppendAsTraceFormat(out); else AppendValueAsJSON(arg_types_[i], arg_values_[i], out); } else { *out += "\"__stripped__\""; } } *out += "}"; } if (phase_ == TRACE_EVENT_PHASE_COMPLETE) { int64 duration = duration_.ToInternalValue(); if (duration != -1) StringAppendF(out, ",\"dur\":%" PRId64, duration); if (!thread_timestamp_.is_null()) { int64 thread_duration = thread_duration_.ToInternalValue(); if (thread_duration != -1) StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration); } } // Output tts if thread_timestamp is valid. if (!thread_timestamp_.is_null()) { int64 thread_time_int64 = thread_timestamp_.ToInternalValue(); StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64); } // Output async tts marker field if flag is set. if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) { StringAppendF(out, ", \"use_async_tts\":1"); } // If id_ is set, print it out as a hex string so we don't loose any // bits (it might be a 64-bit pointer). if (flags_ & TRACE_EVENT_FLAG_HAS_ID) StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast(id_)); if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING) StringAppendF(out, ",\"bp\":\"e\""); if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) || (flags_ & TRACE_EVENT_FLAG_FLOW_IN)) { StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"", static_cast(bind_id_)); } if (flags_ & TRACE_EVENT_FLAG_FLOW_IN) StringAppendF(out, ",\"flow_in\":true"); if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT) StringAppendF(out, ",\"flow_out\":true"); // Similar to id_, print the context_id as hex if present. if (flags_ & TRACE_EVENT_FLAG_HAS_CONTEXT_ID) StringAppendF(out, ",\"cid\":\"0x%" PRIx64 "\"", static_cast(context_id_)); // Instant events also output their scope. if (phase_ == TRACE_EVENT_PHASE_INSTANT) { char scope = '?'; switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) { case TRACE_EVENT_SCOPE_GLOBAL: scope = TRACE_EVENT_SCOPE_NAME_GLOBAL; break; case TRACE_EVENT_SCOPE_PROCESS: scope = TRACE_EVENT_SCOPE_NAME_PROCESS; break; case TRACE_EVENT_SCOPE_THREAD: scope = TRACE_EVENT_SCOPE_NAME_THREAD; break; } StringAppendF(out, ",\"s\":\"%c\"", scope); } *out += "}"; } void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const { *out << name_ << "["; *out << TraceLog::GetCategoryGroupName(category_group_enabled_); *out << "]"; if (arg_names_[0]) { *out << ", {"; for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) { if (i > 0) *out << ", "; *out << arg_names_[i] << ":"; std::string value_as_text; if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE) convertable_values_[i]->AppendAsTraceFormat(&value_as_text); else AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text); *out << value_as_text; } *out << "}"; } } } // namespace trace_event } // namespace base