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/process/process_handle.h"
12 #include "base/stl_util.h"
13 #include "base/strings/string_number_conversions.h"
14 #include "base/strings/string_util.h"
15 #include "base/strings/stringprintf.h"
16 #include "base/strings/utf_string_conversions.h"
17 #include "base/trace_event/trace_event.h"
18 #include "base/trace_event/trace_log.h"
19
20 namespace base {
21 namespace trace_event {
22
23 namespace {
24
GetAllocLength(const char * str)25 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
26
27 // Copies |*member| into |*buffer|, sets |*member| to point to this new
28 // location, and then advances |*buffer| by the amount written.
CopyTraceEventParameter(char ** buffer,const char ** member,const char * end)29 void CopyTraceEventParameter(char** buffer,
30 const char** member,
31 const char* end) {
32 if (*member) {
33 size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
34 DCHECK_LE(static_cast<int>(written), end - *buffer);
35 *member = *buffer;
36 *buffer += written;
37 }
38 }
39
40 } // namespace
41
TraceEvent()42 TraceEvent::TraceEvent()
43 : duration_(TimeDelta::FromInternalValue(-1)),
44 scope_(trace_event_internal::kGlobalScope),
45 id_(0u),
46 category_group_enabled_(NULL),
47 name_(NULL),
48 thread_id_(0),
49 flags_(0),
50 phase_(TRACE_EVENT_PHASE_BEGIN) {
51 for (int i = 0; i < kTraceMaxNumArgs; ++i)
52 arg_names_[i] = NULL;
53 memset(arg_values_, 0, sizeof(arg_values_));
54 }
55
~TraceEvent()56 TraceEvent::~TraceEvent() {
57 }
58
MoveFrom(std::unique_ptr<TraceEvent> other)59 void TraceEvent::MoveFrom(std::unique_ptr<TraceEvent> other) {
60 timestamp_ = other->timestamp_;
61 thread_timestamp_ = other->thread_timestamp_;
62 duration_ = other->duration_;
63 scope_ = other->scope_;
64 id_ = other->id_;
65 category_group_enabled_ = other->category_group_enabled_;
66 name_ = other->name_;
67 if (other->flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID)
68 process_id_ = other->process_id_;
69 else
70 thread_id_ = other->thread_id_;
71 phase_ = other->phase_;
72 flags_ = other->flags_;
73 parameter_copy_storage_ = std::move(other->parameter_copy_storage_);
74
75 for (int i = 0; i < kTraceMaxNumArgs; ++i) {
76 arg_names_[i] = other->arg_names_[i];
77 arg_types_[i] = other->arg_types_[i];
78 arg_values_[i] = other->arg_values_[i];
79 convertable_values_[i] = std::move(other->convertable_values_[i]);
80 }
81 }
82
Initialize(int 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,int num_args,const char ** arg_names,const unsigned char * arg_types,const unsigned long long * arg_values,std::unique_ptr<ConvertableToTraceFormat> * convertable_values,unsigned int flags)83 void TraceEvent::Initialize(
84 int thread_id,
85 TimeTicks timestamp,
86 ThreadTicks thread_timestamp,
87 char phase,
88 const unsigned char* category_group_enabled,
89 const char* name,
90 const char* scope,
91 unsigned long long id,
92 unsigned long long bind_id,
93 int num_args,
94 const char** arg_names,
95 const unsigned char* arg_types,
96 const unsigned long long* arg_values,
97 std::unique_ptr<ConvertableToTraceFormat>* convertable_values,
98 unsigned int flags) {
99 timestamp_ = timestamp;
100 thread_timestamp_ = thread_timestamp;
101 duration_ = TimeDelta::FromInternalValue(-1);
102 scope_ = scope;
103 id_ = id;
104 category_group_enabled_ = category_group_enabled;
105 name_ = name;
106 thread_id_ = thread_id;
107 phase_ = phase;
108 flags_ = flags;
109 bind_id_ = bind_id;
110
111 // Clamp num_args since it may have been set by a third_party library.
112 num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
113 int i = 0;
114 for (; i < num_args; ++i) {
115 arg_names_[i] = arg_names[i];
116 arg_types_[i] = arg_types[i];
117
118 if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
119 convertable_values_[i] = std::move(convertable_values[i]);
120 } else {
121 arg_values_[i].as_uint = arg_values[i];
122 convertable_values_[i].reset();
123 }
124 }
125 for (; i < kTraceMaxNumArgs; ++i) {
126 arg_names_[i] = NULL;
127 arg_values_[i].as_uint = 0u;
128 convertable_values_[i].reset();
129 arg_types_[i] = TRACE_VALUE_TYPE_UINT;
130 }
131
132 bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
133 size_t alloc_size = 0;
134 if (copy) {
135 alloc_size += GetAllocLength(name) + GetAllocLength(scope);
136 for (i = 0; i < num_args; ++i) {
137 alloc_size += GetAllocLength(arg_names_[i]);
138 if (arg_types_[i] == TRACE_VALUE_TYPE_STRING)
139 arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING;
140 }
141 }
142
143 bool arg_is_copy[kTraceMaxNumArgs];
144 for (i = 0; i < num_args; ++i) {
145 // No copying of convertable types, we retain ownership.
146 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
147 continue;
148
149 // We only take a copy of arg_vals if they are of type COPY_STRING.
150 arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
151 if (arg_is_copy[i])
152 alloc_size += GetAllocLength(arg_values_[i].as_string);
153 }
154
155 if (alloc_size) {
156 parameter_copy_storage_.reset(new std::string);
157 parameter_copy_storage_->resize(alloc_size);
158 char* ptr = string_as_array(parameter_copy_storage_.get());
159 const char* end = ptr + alloc_size;
160 if (copy) {
161 CopyTraceEventParameter(&ptr, &name_, end);
162 CopyTraceEventParameter(&ptr, &scope_, end);
163 for (i = 0; i < num_args; ++i) {
164 CopyTraceEventParameter(&ptr, &arg_names_[i], end);
165 }
166 }
167 for (i = 0; i < num_args; ++i) {
168 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
169 continue;
170 if (arg_is_copy[i])
171 CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
172 }
173 DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
174 }
175 }
176
Reset()177 void TraceEvent::Reset() {
178 // Only reset fields that won't be initialized in Initialize(), or that may
179 // hold references to other objects.
180 duration_ = TimeDelta::FromInternalValue(-1);
181 parameter_copy_storage_.reset();
182 for (int i = 0; i < kTraceMaxNumArgs; ++i)
183 convertable_values_[i].reset();
184 }
185
UpdateDuration(const TimeTicks & now,const ThreadTicks & thread_now)186 void TraceEvent::UpdateDuration(const TimeTicks& now,
187 const ThreadTicks& thread_now) {
188 DCHECK_EQ(duration_.ToInternalValue(), -1);
189 duration_ = now - timestamp_;
190
191 // |thread_timestamp_| can be empty if the thread ticks clock wasn't
192 // initialized when it was recorded.
193 if (thread_timestamp_ != ThreadTicks())
194 thread_duration_ = thread_now - thread_timestamp_;
195 }
196
EstimateTraceMemoryOverhead(TraceEventMemoryOverhead * overhead)197 void TraceEvent::EstimateTraceMemoryOverhead(
198 TraceEventMemoryOverhead* overhead) {
199 overhead->Add("TraceEvent", sizeof(*this));
200
201 if (parameter_copy_storage_)
202 overhead->AddString(*parameter_copy_storage_);
203
204 for (size_t i = 0; i < kTraceMaxNumArgs; ++i) {
205 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
206 convertable_values_[i]->EstimateTraceMemoryOverhead(overhead);
207 }
208 }
209
210 // static
AppendValueAsJSON(unsigned char type,TraceEvent::TraceValue value,std::string * out)211 void TraceEvent::AppendValueAsJSON(unsigned char type,
212 TraceEvent::TraceValue value,
213 std::string* out) {
214 switch (type) {
215 case TRACE_VALUE_TYPE_BOOL:
216 *out += value.as_bool ? "true" : "false";
217 break;
218 case TRACE_VALUE_TYPE_UINT:
219 StringAppendF(out, "%" PRIu64, static_cast<uint64_t>(value.as_uint));
220 break;
221 case TRACE_VALUE_TYPE_INT:
222 StringAppendF(out, "%" PRId64, static_cast<int64_t>(value.as_int));
223 break;
224 case TRACE_VALUE_TYPE_DOUBLE: {
225 // FIXME: base/json/json_writer.cc is using the same code,
226 // should be made into a common method.
227 std::string real;
228 double val = value.as_double;
229 if (std::isfinite(val)) {
230 real = DoubleToString(val);
231 // Ensure that the number has a .0 if there's no decimal or 'e'. This
232 // makes sure that when we read the JSON back, it's interpreted as a
233 // real rather than an int.
234 if (real.find('.') == std::string::npos &&
235 real.find('e') == std::string::npos &&
236 real.find('E') == std::string::npos) {
237 real.append(".0");
238 }
239 // The JSON spec requires that non-integer values in the range (-1,1)
240 // have a zero before the decimal point - ".52" is not valid, "0.52" is.
241 if (real[0] == '.') {
242 real.insert(0, "0");
243 } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
244 // "-.1" bad "-0.1" good
245 real.insert(1, "0");
246 }
247 } else if (std::isnan(val)){
248 // The JSON spec doesn't allow NaN and Infinity (since these are
249 // objects in EcmaScript). Use strings instead.
250 real = "\"NaN\"";
251 } else if (val < 0) {
252 real = "\"-Infinity\"";
253 } else {
254 real = "\"Infinity\"";
255 }
256 StringAppendF(out, "%s", real.c_str());
257 break;
258 }
259 case TRACE_VALUE_TYPE_POINTER:
260 // JSON only supports double and int numbers.
261 // So as not to lose bits from a 64-bit pointer, output as a hex string.
262 StringAppendF(
263 out, "\"0x%" PRIx64 "\"",
264 static_cast<uint64_t>(reinterpret_cast<uintptr_t>(value.as_pointer)));
265 break;
266 case TRACE_VALUE_TYPE_STRING:
267 case TRACE_VALUE_TYPE_COPY_STRING:
268 EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
269 break;
270 default:
271 NOTREACHED() << "Don't know how to print this value";
272 break;
273 }
274 }
275
AppendAsJSON(std::string * out,const ArgumentFilterPredicate & argument_filter_predicate) const276 void TraceEvent::AppendAsJSON(
277 std::string* out,
278 const ArgumentFilterPredicate& argument_filter_predicate) const {
279 int64_t time_int64 = timestamp_.ToInternalValue();
280 int process_id;
281 int thread_id;
282 if ((flags_ & TRACE_EVENT_FLAG_HAS_PROCESS_ID) &&
283 process_id_ != kNullProcessId) {
284 process_id = process_id_;
285 thread_id = -1;
286 } else {
287 process_id = TraceLog::GetInstance()->process_id();
288 thread_id = thread_id_;
289 }
290 const char* category_group_name =
291 TraceLog::GetCategoryGroupName(category_group_enabled_);
292
293 // Category group checked at category creation time.
294 DCHECK(!strchr(name_, '"'));
295 StringAppendF(out, "{\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64
296 ",\"ph\":\"%c\",\"cat\":\"%s\",\"name\":",
297 process_id, thread_id, time_int64, phase_, category_group_name);
298 EscapeJSONString(name_, true, out);
299 *out += ",\"args\":";
300
301 // Output argument names and values, stop at first NULL argument name.
302 // TODO(oysteine): The dual predicates here is a bit ugly; if the filtering
303 // capabilities need to grow even more precise we should rethink this
304 // approach
305 ArgumentNameFilterPredicate argument_name_filter_predicate;
306 bool strip_args =
307 arg_names_[0] && !argument_filter_predicate.is_null() &&
308 !argument_filter_predicate.Run(category_group_name, name_,
309 &argument_name_filter_predicate);
310
311 if (strip_args) {
312 *out += "\"__stripped__\"";
313 } else {
314 *out += "{";
315
316 for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
317 if (i > 0)
318 *out += ",";
319 *out += "\"";
320 *out += arg_names_[i];
321 *out += "\":";
322
323 if (argument_name_filter_predicate.is_null() ||
324 argument_name_filter_predicate.Run(arg_names_[i])) {
325 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
326 convertable_values_[i]->AppendAsTraceFormat(out);
327 else
328 AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
329 } else {
330 *out += "\"__stripped__\"";
331 }
332 }
333
334 *out += "}";
335 }
336
337 if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
338 int64_t duration = duration_.ToInternalValue();
339 if (duration != -1)
340 StringAppendF(out, ",\"dur\":%" PRId64, duration);
341 if (!thread_timestamp_.is_null()) {
342 int64_t thread_duration = thread_duration_.ToInternalValue();
343 if (thread_duration != -1)
344 StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
345 }
346 }
347
348 // Output tts if thread_timestamp is valid.
349 if (!thread_timestamp_.is_null()) {
350 int64_t thread_time_int64 = thread_timestamp_.ToInternalValue();
351 StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
352 }
353
354 // Output async tts marker field if flag is set.
355 if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
356 StringAppendF(out, ", \"use_async_tts\":1");
357 }
358
359 // If id_ is set, print it out as a hex string so we don't loose any
360 // bits (it might be a 64-bit pointer).
361 if (flags_ & TRACE_EVENT_FLAG_HAS_ID) {
362 if (scope_ != trace_event_internal::kGlobalScope)
363 StringAppendF(out, ",\"scope\":\"%s\"", scope_);
364 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64_t>(id_));
365 }
366
367 if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
368 StringAppendF(out, ",\"bp\":\"e\"");
369
370 if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) ||
371 (flags_ & TRACE_EVENT_FLAG_FLOW_IN)) {
372 StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"",
373 static_cast<uint64_t>(bind_id_));
374 }
375 if (flags_ & TRACE_EVENT_FLAG_FLOW_IN)
376 StringAppendF(out, ",\"flow_in\":true");
377 if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT)
378 StringAppendF(out, ",\"flow_out\":true");
379
380 // Instant events also output their scope.
381 if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
382 char scope = '?';
383 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
384 case TRACE_EVENT_SCOPE_GLOBAL:
385 scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
386 break;
387
388 case TRACE_EVENT_SCOPE_PROCESS:
389 scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
390 break;
391
392 case TRACE_EVENT_SCOPE_THREAD:
393 scope = TRACE_EVENT_SCOPE_NAME_THREAD;
394 break;
395 }
396 StringAppendF(out, ",\"s\":\"%c\"", scope);
397 }
398
399 *out += "}";
400 }
401
AppendPrettyPrinted(std::ostringstream * out) const402 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
403 *out << name_ << "[";
404 *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
405 *out << "]";
406 if (arg_names_[0]) {
407 *out << ", {";
408 for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
409 if (i > 0)
410 *out << ", ";
411 *out << arg_names_[i] << ":";
412 std::string value_as_text;
413
414 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
415 convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
416 else
417 AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);
418
419 *out << value_as_text;
420 }
421 *out << "}";
422 }
423 }
424
425 } // namespace trace_event
426 } // namespace base
427