1 // Copyright 2012 The Chromium Authors
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 <sstream>
10
11 #include "base/format_macros.h"
12 #include "base/json/string_escape.h"
13 #include "base/memory/ptr_util.h"
14 #include "base/notreached.h"
15 #include "base/process/process_handle.h"
16 #include "base/strings/string_number_conversions.h"
17 #include "base/strings/string_util.h"
18 #include "base/strings/stringprintf.h"
19 #include "base/strings/utf_string_conversions.h"
20 #include "base/trace_event/trace_event.h"
21 #include "base/trace_event/trace_log.h"
22 #include "base/trace_event/traced_value.h"
23 #include "build/build_config.h"
24
25 #if BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
26
27 // Define static storage for trace event categories (see
28 // PERFETTO_DEFINE_CATEGORIES).
29 PERFETTO_TRACK_EVENT_STATIC_STORAGE_IN_NAMESPACE_WITH_ATTRS(base, BASE_EXPORT);
30
31 namespace perfetto {
32 namespace legacy {
33
34 template <>
ConvertThreadId(const::base::PlatformThreadId & thread)35 perfetto::ThreadTrack ConvertThreadId(const ::base::PlatformThreadId& thread) {
36 return perfetto::ThreadTrack::ForThread(thread);
37 }
38
39 } // namespace legacy
40
41 TraceTimestamp
ConvertTimestampToTraceTimeNs(const::base::TimeTicks & ticks)42 TraceTimestampTraits<::base::TimeTicks>::ConvertTimestampToTraceTimeNs(
43 const ::base::TimeTicks& ticks) {
44 return {static_cast<uint32_t>(::base::TrackEvent::GetTraceClockId()),
45 static_cast<uint64_t>(ticks.since_origin().InNanoseconds())};
46 }
47
48 namespace internal {
49
WriteDebugAnnotation(protos::pbzero::DebugAnnotation * annotation,::base::TimeTicks ticks)50 void WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation,
51 ::base::TimeTicks ticks) {
52 annotation->set_int_value(ticks.since_origin().InMilliseconds());
53 }
54
WriteDebugAnnotation(protos::pbzero::DebugAnnotation * annotation,::base::Time time)55 void WriteDebugAnnotation(protos::pbzero::DebugAnnotation* annotation,
56 ::base::Time time) {
57 annotation->set_int_value(time.since_origin().InMilliseconds());
58 }
59
60 } // namespace internal
61 } // namespace perfetto
62
63 #endif // BUILDFLAG(USE_PERFETTO_CLIENT_LIBRARY)
64
65 namespace base {
66 namespace trace_event {
67
AppendToProto(ProtoAppender * appender) const68 bool ConvertableToTraceFormat::AppendToProto(ProtoAppender* appender) const {
69 return false;
70 }
71
72 // See comment for name TraceEvent::scope_ definition.
73 static_assert(trace_event_internal::kGlobalScope == nullptr,
74 "Invalid TraceEvent::scope default initializer value");
75
76 TraceEvent::TraceEvent() = default;
77
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)78 TraceEvent::TraceEvent(PlatformThreadId thread_id,
79 TimeTicks timestamp,
80 ThreadTicks thread_timestamp,
81 char phase,
82 const unsigned char* category_group_enabled,
83 const char* name,
84 const char* scope,
85 unsigned long long id,
86 unsigned long long bind_id,
87 TraceArguments* args,
88 unsigned int flags)
89 : timestamp_(timestamp),
90 thread_timestamp_(thread_timestamp),
91 scope_(scope),
92 id_(id),
93 category_group_enabled_(category_group_enabled),
94 name_(name),
95 thread_id_(thread_id),
96 flags_(flags),
97 bind_id_(bind_id),
98 phase_(phase) {
99 InitArgs(args);
100 }
101
102 TraceEvent::~TraceEvent() = default;
103
104 TraceEvent::TraceEvent(TraceEvent&& other) noexcept = default;
105 TraceEvent& TraceEvent::operator=(TraceEvent&& other) noexcept = default;
106
Reset()107 void TraceEvent::Reset() {
108 // Only reset fields that won't be initialized in Reset(int, ...), or that may
109 // hold references to other objects.
110 duration_ = TimeDelta::FromInternalValue(-1);
111 args_.Reset();
112 parameter_copy_storage_.Reset();
113 }
114
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)115 void TraceEvent::Reset(PlatformThreadId thread_id,
116 TimeTicks timestamp,
117 ThreadTicks thread_timestamp,
118 char phase,
119 const unsigned char* category_group_enabled,
120 const char* name,
121 const char* scope,
122 unsigned long long id,
123 unsigned long long bind_id,
124 TraceArguments* args,
125 unsigned int flags) {
126 Reset();
127 timestamp_ = timestamp;
128 thread_timestamp_ = thread_timestamp;
129 scope_ = scope;
130 id_ = id;
131 category_group_enabled_ = category_group_enabled;
132 name_ = name;
133 thread_id_ = thread_id;
134 flags_ = flags;
135 bind_id_ = bind_id;
136 phase_ = phase;
137
138 InitArgs(args);
139 }
140
InitArgs(TraceArguments * args)141 void TraceEvent::InitArgs(TraceArguments* args) {
142 if (args)
143 args_ = std::move(*args);
144 args_.CopyStringsTo(¶meter_copy_storage_,
145 !!(flags_ & TRACE_EVENT_FLAG_COPY), &name_, &scope_);
146 }
147
UpdateDuration(const TimeTicks & now,const ThreadTicks & thread_now)148 void TraceEvent::UpdateDuration(const TimeTicks& now,
149 const ThreadTicks& thread_now) {
150 DCHECK_EQ(duration_.ToInternalValue(), -1);
151 duration_ = now - timestamp_;
152
153 // |thread_timestamp_| can be empty if the thread ticks clock wasn't
154 // initialized when it was recorded.
155 if (thread_timestamp_ != ThreadTicks())
156 thread_duration_ = thread_now - thread_timestamp_;
157 }
158
EstimateTraceMemoryOverhead(TraceEventMemoryOverhead * overhead)159 void TraceEvent::EstimateTraceMemoryOverhead(
160 TraceEventMemoryOverhead* overhead) {
161 overhead->Add(TraceEventMemoryOverhead::kTraceEvent,
162 parameter_copy_storage_.EstimateTraceMemoryOverhead());
163
164 for (size_t i = 0; i < arg_size(); ++i) {
165 if (arg_type(i) == TRACE_VALUE_TYPE_CONVERTABLE)
166 arg_value(i).as_convertable->EstimateTraceMemoryOverhead(overhead);
167 }
168 }
169
AppendAsJSON(std::string * out,const ArgumentFilterPredicate & argument_filter_predicate) const170 void TraceEvent::AppendAsJSON(
171 std::string* out,
172 const ArgumentFilterPredicate& argument_filter_predicate) const {
173 int64_t time_int64 = timestamp_.ToInternalValue();
174 ProcessId process_id;
175 PlatformThreadId thread_id;
176 if ((flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) &&
177 process_id_ != kNullProcessId) {
178 process_id = process_id_;
179 thread_id = static_cast<PlatformThreadId>(-1);
180 } else {
181 process_id = TraceLog::GetInstance()->process_id();
182 thread_id = thread_id_;
183 }
184 const char* category_group_name =
185 TraceLog::GetCategoryGroupName(category_group_enabled_);
186
187 // Category group checked at category creation time.
188 DCHECK(!strchr(name_, '"'));
189 StringAppendF(out,
190 "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64
191 ",\"ph\":\"%c\",\"cat\":\"%s\",\"name\":",
192 static_cast<int>(process_id), static_cast<int>(thread_id),
193 time_int64, phase_, category_group_name);
194 EscapeJSONString(name_, true, out);
195 *out += ",\"args\":";
196
197 // Output argument names and values, stop at first NULL argument name.
198 // TODO(oysteine): The dual predicates here is a bit ugly; if the filtering
199 // capabilities need to grow even more precise we should rethink this
200 // approach
201 ArgumentNameFilterPredicate argument_name_filter_predicate;
202 bool strip_args =
203 arg_size() > 0 && arg_name(0) && !argument_filter_predicate.is_null() &&
204 !argument_filter_predicate.Run(category_group_name, name_,
205 &argument_name_filter_predicate);
206
207 if (strip_args) {
208 *out += "\"__stripped__\"";
209 } else {
210 *out += "{";
211
212 for (size_t i = 0; i < arg_size() && arg_name(i); ++i) {
213 if (i > 0)
214 *out += ",";
215 *out += "\"";
216 *out += arg_name(i);
217 *out += "\":";
218
219 if (argument_name_filter_predicate.is_null() ||
220 argument_name_filter_predicate.Run(arg_name(i))) {
221 arg_value(i).AppendAsJSON(arg_type(i), out);
222 } else {
223 *out += "\"__stripped__\"";
224 }
225 }
226
227 *out += "}";
228 }
229
230 if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
231 int64_t duration = duration_.ToInternalValue();
232 if (duration != -1)
233 StringAppendF(out, ",\"dur\":%" PRId64, duration);
234 if (!thread_timestamp_.is_null()) {
235 int64_t thread_duration = thread_duration_.ToInternalValue();
236 if (thread_duration != -1)
237 StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
238 }
239 }
240
241 // Output tts if thread_timestamp is valid.
242 if (!thread_timestamp_.is_null()) {
243 int64_t thread_time_int64 = thread_timestamp_.ToInternalValue();
244 StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
245 }
246
247 // Output async tts marker field if flag is set.
248 if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
249 StringAppendF(out, ", \"use_async_tts\":1");
250 }
251
252 // If id_ is set, print it out as a hex string so we don't loose any
253 // bits (it might be a 64-bit pointer).
254 unsigned int id_flags_ = flags_ & (TRACE_EVENT_FLAG_HAS_ID |
255 TRACE_EVENT_FLAG_HAS_LOCAL_ID |
256 TRACE_EVENT_FLAG_HAS_GLOBAL_ID);
257 if (id_flags_) {
258 if (scope_ != trace_event_internal::kGlobalScope)
259 StringAppendF(out, ",\"scope\":\"%s\"", scope_);
260
261 switch (id_flags_) {
262 case TRACE_EVENT_FLAG_HAS_ID:
263 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"",
264 static_cast<uint64_t>(id_));
265 break;
266
267 case TRACE_EVENT_FLAG_HAS_LOCAL_ID:
268 StringAppendF(out, ",\"id2\":{\"local\":\"0x%" PRIx64 "\"}",
269 static_cast<uint64_t>(id_));
270 break;
271
272 case TRACE_EVENT_FLAG_HAS_GLOBAL_ID:
273 StringAppendF(out, ",\"id2\":{\"global\":\"0x%" PRIx64 "\"}",
274 static_cast<uint64_t>(id_));
275 break;
276
277 default:
278 NOTREACHED() << "More than one of the ID flags are set";
279 break;
280 }
281 }
282
283 if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
284 StringAppendF(out, ",\"bp\":\"e\"");
285
286 if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) ||
287 (flags_ & TRACE_EVENT_FLAG_FLOW_IN)) {
288 StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"",
289 static_cast<uint64_t>(bind_id_));
290 }
291 if (flags_ & TRACE_EVENT_FLAG_FLOW_IN)
292 StringAppendF(out, ",\"flow_in\":true");
293 if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT)
294 StringAppendF(out, ",\"flow_out\":true");
295
296 // Instant events also output their scope.
297 if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
298 char scope = '?';
299 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
300 case TRACE_EVENT_SCOPE_GLOBAL:
301 scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
302 break;
303
304 case TRACE_EVENT_SCOPE_PROCESS:
305 scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
306 break;
307
308 case TRACE_EVENT_SCOPE_THREAD:
309 scope = TRACE_EVENT_SCOPE_NAME_THREAD;
310 break;
311 }
312 StringAppendF(out, ",\"s\":\"%c\"", scope);
313 }
314
315 *out += "}";
316 }
317
AppendPrettyPrinted(std::ostringstream * out) const318 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
319 *out << name_ << "[";
320 *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
321 *out << "]";
322 if (arg_size() > 0 && arg_name(0)) {
323 *out << ", {";
324 for (size_t i = 0; i < arg_size() && arg_name(i); ++i) {
325 if (i > 0)
326 *out << ", ";
327 *out << arg_name(i) << ":";
328 std::string value_as_text;
329 arg_value(i).AppendAsJSON(arg_type(i), &value_as_text);
330 *out << value_as_text;
331 }
332 *out << "}";
333 }
334 }
335
336 } // namespace trace_event
337 } // namespace base
338