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