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