// Copyright 2012 The Chromium Authors // 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 #include #include "base/format_macros.h" #include "base/json/string_escape.h" #include "base/memory/ptr_util.h" #include "base/notreached.h" #include "base/process/process_handle.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" #include "base/trace_event/traced_value.h" #include "build/build_config.h" #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY) // Define static storage for trace event categories (see // PERFETTO_DEFINE_CATEGORIES). PERFETTO_TRACK_EVENT_STATIC_STORAGE_IN_NAMESPACE_WITH_ATTRS(base, BASE_EXPORT); namespace perfetto { namespace legacy { template <> perfetto::ThreadTrack ConvertThreadId(const ::base::PlatformThreadId& thread) { return perfetto::ThreadTrack::ForThread(thread); } } // namespace legacy TraceTimestamp TraceTimestampTraits<::base::TimeTicks>::ConvertTimestampToTraceTimeNs( const ::base::TimeTicks& ticks) { return {static_cast(::base::TrackEvent::GetTraceClockId()), static_cast(ticks.since_origin().InNanoseconds())}; } namespace internal { void WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation, ::base::TimeTicks ticks) { annotation->set_int_value(ticks.since_origin().InMilliseconds()); } void WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation, ::base::Time time) { annotation->set_int_value(time.since_origin().InMilliseconds()); } } // namespace internal } // namespace perfetto #endif // BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY) namespace base { namespace trace_event { bool ConvertableToTraceFormat::AppendToProto(ProtoAppender* appender) const { return false; } // See comment for name TraceEvent::scope_ definition. static_assert(trace_event_internal::kGlobalScope == nullptr, "Invalid TraceEvent::scope default initializer value"); TraceEvent::TraceEvent() = default; TraceEvent::TraceEvent(PlatformThreadId thread_id, TimeTicks timestamp, ThreadTicks thread_timestamp, char phase, const unsigned char* category_group_enabled, const char* name, const char* scope, unsigned long long id, unsigned long long bind_id, TraceArguments* args, unsigned int flags) : timestamp_(timestamp), thread_timestamp_(thread_timestamp), scope_(scope), id_(id), category_group_enabled_(category_group_enabled), name_(name), thread_id_(thread_id), flags_(flags), bind_id_(bind_id), phase_(phase) { InitArgs(args); } TraceEvent::~TraceEvent() = default; TraceEvent::TraceEvent(TraceEvent&& other) noexcept = default; TraceEvent& TraceEvent::operator=(TraceEvent&& other) noexcept = default; void TraceEvent::Reset() { // Only reset fields that won't be initialized in Reset(int, ...), or that may // hold references to other objects. duration_ = TimeDelta::FromInternalValue(-1); args_.Reset(); parameter_copy_storage_.Reset(); } void TraceEvent::Reset(PlatformThreadId thread_id, TimeTicks timestamp, ThreadTicks thread_timestamp, char phase, const unsigned char* category_group_enabled, const char* name, const char* scope, unsigned long long id, unsigned long long bind_id, TraceArguments* args, unsigned int flags) { Reset(); timestamp_ = timestamp; thread_timestamp_ = thread_timestamp; scope_ = scope; id_ = id; category_group_enabled_ = category_group_enabled; name_ = name; thread_id_ = thread_id; flags_ = flags; bind_id_ = bind_id; phase_ = phase; InitArgs(args); } void TraceEvent::InitArgs(TraceArguments* args) { if (args) args_ = std::move(*args); args_.CopyStringsTo(¶meter_copy_storage_, !!(flags_ & TRACE_EVENT_FLAG_COPY), &name_, &scope_); } 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(TraceEventMemoryOverhead::kTraceEvent, parameter_copy_storage_.EstimateTraceMemoryOverhead()); for (size_t i = 0; i < arg_size(); ++i) { if (arg_type(i) == TRACE_VALUE_TYPE_CONVERTABLE) arg_value(i).as_convertable->EstimateTraceMemoryOverhead(overhead); } } void TraceEvent::AppendAsJSON( std::string* out, const ArgumentFilterPredicate& argument_filter_predicate) const { int64_t time_int64 = timestamp_.ToInternalValue(); ProcessId process_id; PlatformThreadId thread_id; if ((flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) && process_id_ != kNullProcessId) { process_id = process_id_; thread_id = static_cast(-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\":", static_cast(process_id), static_cast(thread_id), time_int64, phase_, category_group_name); EscapeJSONString(name_, true, out); *out += ",\"args\":"; // 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_size() > 0 && arg_name(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 (size_t i = 0; i < arg_size() && arg_name(i); ++i) { if (i > 0) *out += ","; *out += "\""; *out += arg_name(i); *out += "\":"; if (argument_name_filter_predicate.is_null() || argument_name_filter_predicate.Run(arg_name(i))) { arg_value(i).AppendAsJSON(arg_type(i), out); } else { *out += "\"__stripped__\""; } } *out += "}"; } if (phase_ == TRACE_EVENT_PHASE_COMPLETE) { int64_t duration = duration_.ToInternalValue(); if (duration != -1) StringAppendF(out, ",\"dur\":%" PRId64, duration); if (!thread_timestamp_.is_null()) { int64_t 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_t 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). unsigned int id_flags_ = flags_ & (TRACE_EVENT_FLAG_HAS_ID | TRACE_EVENT_FLAG_HAS_LOCAL_ID | TRACE_EVENT_FLAG_HAS_GLOBAL_ID); if (id_flags_) { if (scope_ != trace_event_internal::kGlobalScope) StringAppendF(out, ",\"scope\":\"%s\"", scope_); switch (id_flags_) { case TRACE_EVENT_FLAG_HAS_ID: StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast(id_)); break; case TRACE_EVENT_FLAG_HAS_LOCAL_ID: StringAppendF(out, ",\"id2\":{\"local\":\"0x%" PRIx64 "\"}", static_cast(id_)); break; case TRACE_EVENT_FLAG_HAS_GLOBAL_ID: StringAppendF(out, ",\"id2\":{\"global\":\"0x%" PRIx64 "\"}", static_cast(id_)); break; default: NOTREACHED() << "More than one of the ID flags are set"; break; } } 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"); // 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_size() > 0 && arg_name(0)) { *out << ", {"; for (size_t i = 0; i < arg_size() && arg_name(i); ++i) { if (i > 0) *out << ", "; *out << arg_name(i) << ":"; std::string value_as_text; arg_value(i).AppendAsJSON(arg_type(i), &value_as_text); *out << value_as_text; } *out << "}"; } } } // namespace trace_event } // namespace base