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/debug/trace_event_impl.h"
6
7 #include <algorithm>
8
9 #include "base/base_switches.h"
10 #include "base/bind.h"
11 #include "base/command_line.h"
12 #include "base/debug/leak_annotations.h"
13 #include "base/debug/trace_event.h"
14 #include "base/format_macros.h"
15 #include "base/json/string_escape.h"
16 #include "base/lazy_instance.h"
17 #include "base/memory/singleton.h"
18 #include "base/message_loop/message_loop.h"
19 #include "base/process/process_metrics.h"
20 #include "base/stl_util.h"
21 #include "base/strings/string_number_conversions.h"
22 #include "base/strings/string_split.h"
23 #include "base/strings/string_tokenizer.h"
24 #include "base/strings/string_util.h"
25 #include "base/strings/stringprintf.h"
26 #include "base/strings/utf_string_conversions.h"
27 #include "base/synchronization/cancellation_flag.h"
28 #include "base/synchronization/waitable_event.h"
29 #include "base/sys_info.h"
30 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
31 #include "base/threading/platform_thread.h"
32 #include "base/threading/thread_id_name_manager.h"
33 #include "base/time/time.h"
34
35 #if defined(OS_WIN)
36 #include "base/debug/trace_event_win.h"
37 #endif
38
39 class DeleteTraceLogForTesting {
40 public:
Delete()41 static void Delete() {
42 Singleton<base::debug::TraceLog,
43 LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0);
44 }
45 };
46
47 // The thread buckets for the sampling profiler.
48 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];
49
50 namespace base {
51 namespace debug {
52
53 namespace {
54
55 // The overhead of TraceEvent above this threshold will be reported in the
56 // trace.
57 const int kOverheadReportThresholdInMicroseconds = 50;
58
59 // Controls the number of trace events we will buffer in-memory
60 // before throwing them away.
61 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize;
62 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
63 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
64 const size_t kTraceEventBatchChunks = 1000 / kTraceBufferChunkSize;
65 // Can store results for 30 seconds with 1 ms sampling interval.
66 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize;
67 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
68 const size_t kEchoToConsoleTraceEventBufferChunks = 256;
69
70 const int kThreadFlushTimeoutMs = 3000;
71
72 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
73 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
74
75 #define MAX_CATEGORY_GROUPS 100
76
77 // Parallel arrays g_category_groups and g_category_group_enabled are separate
78 // so that a pointer to a member of g_category_group_enabled can be easily
79 // converted to an index into g_category_groups. This allows macros to deal
80 // only with char enabled pointers from g_category_group_enabled, and we can
81 // convert internally to determine the category name from the char enabled
82 // pointer.
83 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
84 "tracing already shutdown",
85 "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
86 "__metadata",
87 // For reporting trace_event overhead. For thread local event buffers only.
88 "trace_event_overhead"};
89
90 // The enabled flag is char instead of bool so that the API can be used from C.
91 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = { 0 };
92 const int g_category_already_shutdown = 0;
93 const int g_category_categories_exhausted = 1;
94 const int g_category_metadata = 2;
95 const int g_category_trace_event_overhead = 3;
96 const int g_num_builtin_categories = 4;
97 int g_category_index = g_num_builtin_categories; // Skip default categories.
98
99 // The name of the current thread. This is used to decide if the current
100 // thread name has changed. We combine all the seen thread names into the
101 // output name for the thread.
102 LazyInstance<ThreadLocalPointer<const char> >::Leaky
103 g_current_thread_name = LAZY_INSTANCE_INITIALIZER;
104
ThreadNow()105 TimeTicks ThreadNow() {
106 return TimeTicks::IsThreadNowSupported() ?
107 TimeTicks::ThreadNow() : TimeTicks();
108 }
109
110 class TraceBufferRingBuffer : public TraceBuffer {
111 public:
TraceBufferRingBuffer(size_t max_chunks)112 TraceBufferRingBuffer(size_t max_chunks)
113 : max_chunks_(max_chunks),
114 recyclable_chunks_queue_(new size_t[queue_capacity()]),
115 queue_head_(0),
116 queue_tail_(max_chunks),
117 current_iteration_index_(0),
118 current_chunk_seq_(1) {
119 chunks_.reserve(max_chunks);
120 for (size_t i = 0; i < max_chunks; ++i)
121 recyclable_chunks_queue_[i] = i;
122 }
123
GetChunk(size_t * index)124 virtual scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) OVERRIDE {
125 // Because the number of threads is much less than the number of chunks,
126 // the queue should never be empty.
127 DCHECK(!QueueIsEmpty());
128
129 *index = recyclable_chunks_queue_[queue_head_];
130 queue_head_ = NextQueueIndex(queue_head_);
131 current_iteration_index_ = queue_head_;
132
133 if (*index >= chunks_.size())
134 chunks_.resize(*index + 1);
135
136 TraceBufferChunk* chunk = chunks_[*index];
137 chunks_[*index] = NULL; // Put NULL in the slot of a in-flight chunk.
138 if (chunk)
139 chunk->Reset(current_chunk_seq_++);
140 else
141 chunk = new TraceBufferChunk(current_chunk_seq_++);
142
143 return scoped_ptr<TraceBufferChunk>(chunk);
144 }
145
ReturnChunk(size_t index,scoped_ptr<TraceBufferChunk> chunk)146 virtual void ReturnChunk(size_t index,
147 scoped_ptr<TraceBufferChunk> chunk) OVERRIDE {
148 // When this method is called, the queue should not be full because it
149 // can contain all chunks including the one to be returned.
150 DCHECK(!QueueIsFull());
151 DCHECK(chunk);
152 DCHECK_LT(index, chunks_.size());
153 DCHECK(!chunks_[index]);
154 chunks_[index] = chunk.release();
155 recyclable_chunks_queue_[queue_tail_] = index;
156 queue_tail_ = NextQueueIndex(queue_tail_);
157 }
158
IsFull() const159 virtual bool IsFull() const OVERRIDE {
160 return false;
161 }
162
Size() const163 virtual size_t Size() const OVERRIDE {
164 // This is approximate because not all of the chunks are full.
165 return chunks_.size() * kTraceBufferChunkSize;
166 }
167
Capacity() const168 virtual size_t Capacity() const OVERRIDE {
169 return max_chunks_ * kTraceBufferChunkSize;
170 }
171
GetEventByHandle(TraceEventHandle handle)172 virtual TraceEvent* GetEventByHandle(TraceEventHandle handle) OVERRIDE {
173 if (handle.chunk_index >= chunks_.size())
174 return NULL;
175 TraceBufferChunk* chunk = chunks_[handle.chunk_index];
176 if (!chunk || chunk->seq() != handle.chunk_seq)
177 return NULL;
178 return chunk->GetEventAt(handle.event_index);
179 }
180
NextChunk()181 virtual const TraceBufferChunk* NextChunk() OVERRIDE {
182 if (chunks_.empty())
183 return NULL;
184
185 while (current_iteration_index_ != queue_tail_) {
186 size_t chunk_index = recyclable_chunks_queue_[current_iteration_index_];
187 current_iteration_index_ = NextQueueIndex(current_iteration_index_);
188 if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
189 continue;
190 DCHECK(chunks_[chunk_index]);
191 return chunks_[chunk_index];
192 }
193 return NULL;
194 }
195
CloneForIteration() const196 virtual scoped_ptr<TraceBuffer> CloneForIteration() const OVERRIDE {
197 scoped_ptr<ClonedTraceBuffer> cloned_buffer(new ClonedTraceBuffer());
198 for (size_t queue_index = queue_head_; queue_index != queue_tail_;
199 queue_index = NextQueueIndex(queue_index)) {
200 size_t chunk_index = recyclable_chunks_queue_[queue_index];
201 if (chunk_index >= chunks_.size()) // Skip uninitialized chunks.
202 continue;
203 TraceBufferChunk* chunk = chunks_[chunk_index];
204 cloned_buffer->chunks_.push_back(chunk ? chunk->Clone().release() : NULL);
205 }
206 return cloned_buffer.PassAs<TraceBuffer>();
207 }
208
209 private:
210 class ClonedTraceBuffer : public TraceBuffer {
211 public:
ClonedTraceBuffer()212 ClonedTraceBuffer() : current_iteration_index_(0) {}
213
214 // The only implemented method.
NextChunk()215 virtual const TraceBufferChunk* NextChunk() OVERRIDE {
216 return current_iteration_index_ < chunks_.size() ?
217 chunks_[current_iteration_index_++] : NULL;
218 }
219
GetChunk(size_t * index)220 virtual scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) OVERRIDE {
221 NOTIMPLEMENTED();
222 return scoped_ptr<TraceBufferChunk>();
223 }
ReturnChunk(size_t index,scoped_ptr<TraceBufferChunk>)224 virtual void ReturnChunk(size_t index,
225 scoped_ptr<TraceBufferChunk>) OVERRIDE {
226 NOTIMPLEMENTED();
227 }
IsFull() const228 virtual bool IsFull() const OVERRIDE { return false; }
Size() const229 virtual size_t Size() const OVERRIDE { return 0; }
Capacity() const230 virtual size_t Capacity() const OVERRIDE { return 0; }
GetEventByHandle(TraceEventHandle handle)231 virtual TraceEvent* GetEventByHandle(TraceEventHandle handle) OVERRIDE {
232 return NULL;
233 }
CloneForIteration() const234 virtual scoped_ptr<TraceBuffer> CloneForIteration() const OVERRIDE {
235 NOTIMPLEMENTED();
236 return scoped_ptr<TraceBuffer>();
237 }
238
239 size_t current_iteration_index_;
240 ScopedVector<TraceBufferChunk> chunks_;
241 };
242
QueueIsEmpty() const243 bool QueueIsEmpty() const {
244 return queue_head_ == queue_tail_;
245 }
246
QueueSize() const247 size_t QueueSize() const {
248 return queue_tail_ > queue_head_ ? queue_tail_ - queue_head_ :
249 queue_tail_ + queue_capacity() - queue_head_;
250 }
251
QueueIsFull() const252 bool QueueIsFull() const {
253 return QueueSize() == queue_capacity() - 1;
254 }
255
queue_capacity() const256 size_t queue_capacity() const {
257 // One extra space to help distinguish full state and empty state.
258 return max_chunks_ + 1;
259 }
260
NextQueueIndex(size_t index) const261 size_t NextQueueIndex(size_t index) const {
262 index++;
263 if (index >= queue_capacity())
264 index = 0;
265 return index;
266 }
267
268 size_t max_chunks_;
269 ScopedVector<TraceBufferChunk> chunks_;
270
271 scoped_ptr<size_t[]> recyclable_chunks_queue_;
272 size_t queue_head_;
273 size_t queue_tail_;
274
275 size_t current_iteration_index_;
276 uint32 current_chunk_seq_;
277
278 DISALLOW_COPY_AND_ASSIGN(TraceBufferRingBuffer);
279 };
280
281 class TraceBufferVector : public TraceBuffer {
282 public:
TraceBufferVector()283 TraceBufferVector()
284 : in_flight_chunk_count_(0),
285 current_iteration_index_(0) {
286 chunks_.reserve(kTraceEventVectorBufferChunks);
287 }
288
GetChunk(size_t * index)289 virtual scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) OVERRIDE {
290 // This function may be called when adding normal events or indirectly from
291 // AddMetadataEventsWhileLocked(). We can not DECHECK(!IsFull()) because we
292 // have to add the metadata events and flush thread-local buffers even if
293 // the buffer is full.
294 *index = chunks_.size();
295 chunks_.push_back(NULL); // Put NULL in the slot of a in-flight chunk.
296 ++in_flight_chunk_count_;
297 // + 1 because zero chunk_seq is not allowed.
298 return scoped_ptr<TraceBufferChunk>(
299 new TraceBufferChunk(static_cast<uint32>(*index) + 1));
300 }
301
ReturnChunk(size_t index,scoped_ptr<TraceBufferChunk> chunk)302 virtual void ReturnChunk(size_t index,
303 scoped_ptr<TraceBufferChunk> chunk) OVERRIDE {
304 DCHECK_GT(in_flight_chunk_count_, 0u);
305 DCHECK_LT(index, chunks_.size());
306 DCHECK(!chunks_[index]);
307 --in_flight_chunk_count_;
308 chunks_[index] = chunk.release();
309 }
310
IsFull() const311 virtual bool IsFull() const OVERRIDE {
312 return chunks_.size() >= kTraceEventVectorBufferChunks;
313 }
314
Size() const315 virtual size_t Size() const OVERRIDE {
316 // This is approximate because not all of the chunks are full.
317 return chunks_.size() * kTraceBufferChunkSize;
318 }
319
Capacity() const320 virtual size_t Capacity() const OVERRIDE {
321 return kTraceEventVectorBufferChunks * kTraceBufferChunkSize;
322 }
323
GetEventByHandle(TraceEventHandle handle)324 virtual TraceEvent* GetEventByHandle(TraceEventHandle handle) OVERRIDE {
325 if (handle.chunk_index >= chunks_.size())
326 return NULL;
327 TraceBufferChunk* chunk = chunks_[handle.chunk_index];
328 if (!chunk || chunk->seq() != handle.chunk_seq)
329 return NULL;
330 return chunk->GetEventAt(handle.event_index);
331 }
332
NextChunk()333 virtual const TraceBufferChunk* NextChunk() OVERRIDE {
334 while (current_iteration_index_ < chunks_.size()) {
335 // Skip in-flight chunks.
336 const TraceBufferChunk* chunk = chunks_[current_iteration_index_++];
337 if (chunk)
338 return chunk;
339 }
340 return NULL;
341 }
342
CloneForIteration() const343 virtual scoped_ptr<TraceBuffer> CloneForIteration() const OVERRIDE {
344 NOTIMPLEMENTED();
345 return scoped_ptr<TraceBuffer>();
346 }
347
348 private:
349 size_t in_flight_chunk_count_;
350 size_t current_iteration_index_;
351 ScopedVector<TraceBufferChunk> chunks_;
352
353 DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
354 };
355
356 template <typename T>
InitializeMetadataEvent(TraceEvent * trace_event,int thread_id,const char * metadata_name,const char * arg_name,const T & value)357 void InitializeMetadataEvent(TraceEvent* trace_event,
358 int thread_id,
359 const char* metadata_name, const char* arg_name,
360 const T& value) {
361 if (!trace_event)
362 return;
363
364 int num_args = 1;
365 unsigned char arg_type;
366 unsigned long long arg_value;
367 ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value);
368 trace_event->Initialize(thread_id,
369 TimeTicks(), TimeTicks(), TRACE_EVENT_PHASE_METADATA,
370 &g_category_group_enabled[g_category_metadata],
371 metadata_name, ::trace_event_internal::kNoEventId,
372 num_args, &arg_name, &arg_type, &arg_value, NULL,
373 TRACE_EVENT_FLAG_NONE);
374 }
375
376 class AutoThreadLocalBoolean {
377 public:
AutoThreadLocalBoolean(ThreadLocalBoolean * thread_local_boolean)378 explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean)
379 : thread_local_boolean_(thread_local_boolean) {
380 DCHECK(!thread_local_boolean_->Get());
381 thread_local_boolean_->Set(true);
382 }
~AutoThreadLocalBoolean()383 ~AutoThreadLocalBoolean() {
384 thread_local_boolean_->Set(false);
385 }
386
387 private:
388 ThreadLocalBoolean* thread_local_boolean_;
389 DISALLOW_COPY_AND_ASSIGN(AutoThreadLocalBoolean);
390 };
391
392 } // namespace
393
Reset(uint32 new_seq)394 void TraceBufferChunk::Reset(uint32 new_seq) {
395 for (size_t i = 0; i < next_free_; ++i)
396 chunk_[i].Reset();
397 next_free_ = 0;
398 seq_ = new_seq;
399 }
400
AddTraceEvent(size_t * event_index)401 TraceEvent* TraceBufferChunk::AddTraceEvent(size_t* event_index) {
402 DCHECK(!IsFull());
403 *event_index = next_free_++;
404 return &chunk_[*event_index];
405 }
406
Clone() const407 scoped_ptr<TraceBufferChunk> TraceBufferChunk::Clone() const {
408 scoped_ptr<TraceBufferChunk> cloned_chunk(new TraceBufferChunk(seq_));
409 cloned_chunk->next_free_ = next_free_;
410 for (size_t i = 0; i < next_free_; ++i)
411 cloned_chunk->chunk_[i].CopyFrom(chunk_[i]);
412 return cloned_chunk.Pass();
413 }
414
415 // A helper class that allows the lock to be acquired in the middle of the scope
416 // and unlocks at the end of scope if locked.
417 class TraceLog::OptionalAutoLock {
418 public:
OptionalAutoLock(Lock & lock)419 explicit OptionalAutoLock(Lock& lock)
420 : lock_(lock),
421 locked_(false) {
422 }
423
~OptionalAutoLock()424 ~OptionalAutoLock() {
425 if (locked_)
426 lock_.Release();
427 }
428
EnsureAcquired()429 void EnsureAcquired() {
430 if (!locked_) {
431 lock_.Acquire();
432 locked_ = true;
433 }
434 }
435
436 private:
437 Lock& lock_;
438 bool locked_;
439 DISALLOW_COPY_AND_ASSIGN(OptionalAutoLock);
440 };
441
442 // Use this function instead of TraceEventHandle constructor to keep the
443 // overhead of ScopedTracer (trace_event.h) constructor minimum.
MakeHandle(uint32 chunk_seq,size_t chunk_index,size_t event_index,TraceEventHandle * handle)444 void MakeHandle(uint32 chunk_seq, size_t chunk_index, size_t event_index,
445 TraceEventHandle* handle) {
446 DCHECK(chunk_seq);
447 DCHECK(chunk_index < (1u << 16));
448 DCHECK(event_index < (1u << 16));
449 handle->chunk_seq = chunk_seq;
450 handle->chunk_index = static_cast<uint16>(chunk_index);
451 handle->event_index = static_cast<uint16>(event_index);
452 }
453
454 ////////////////////////////////////////////////////////////////////////////////
455 //
456 // TraceEvent
457 //
458 ////////////////////////////////////////////////////////////////////////////////
459
460 namespace {
461
GetAllocLength(const char * str)462 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
463
464 // Copies |*member| into |*buffer|, sets |*member| to point to this new
465 // location, and then advances |*buffer| by the amount written.
CopyTraceEventParameter(char ** buffer,const char ** member,const char * end)466 void CopyTraceEventParameter(char** buffer,
467 const char** member,
468 const char* end) {
469 if (*member) {
470 size_t written = strlcpy(*buffer, *member, end - *buffer) + 1;
471 DCHECK_LE(static_cast<int>(written), end - *buffer);
472 *member = *buffer;
473 *buffer += written;
474 }
475 }
476
477 } // namespace
478
TraceEvent()479 TraceEvent::TraceEvent()
480 : duration_(TimeDelta::FromInternalValue(-1)),
481 id_(0u),
482 category_group_enabled_(NULL),
483 name_(NULL),
484 thread_id_(0),
485 phase_(TRACE_EVENT_PHASE_BEGIN),
486 flags_(0) {
487 for (int i = 0; i < kTraceMaxNumArgs; ++i)
488 arg_names_[i] = NULL;
489 memset(arg_values_, 0, sizeof(arg_values_));
490 }
491
~TraceEvent()492 TraceEvent::~TraceEvent() {
493 }
494
CopyFrom(const TraceEvent & other)495 void TraceEvent::CopyFrom(const TraceEvent& other) {
496 timestamp_ = other.timestamp_;
497 thread_timestamp_ = other.thread_timestamp_;
498 duration_ = other.duration_;
499 id_ = other.id_;
500 category_group_enabled_ = other.category_group_enabled_;
501 name_ = other.name_;
502 thread_id_ = other.thread_id_;
503 phase_ = other.phase_;
504 flags_ = other.flags_;
505 parameter_copy_storage_ = other.parameter_copy_storage_;
506
507 for (int i = 0; i < kTraceMaxNumArgs; ++i) {
508 arg_names_[i] = other.arg_names_[i];
509 arg_types_[i] = other.arg_types_[i];
510 arg_values_[i] = other.arg_values_[i];
511 convertable_values_[i] = other.convertable_values_[i];
512 }
513 }
514
Initialize(int thread_id,TimeTicks timestamp,TimeTicks thread_timestamp,char phase,const unsigned char * category_group_enabled,const char * name,unsigned long long 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 char flags)515 void TraceEvent::Initialize(
516 int thread_id,
517 TimeTicks timestamp,
518 TimeTicks thread_timestamp,
519 char phase,
520 const unsigned char* category_group_enabled,
521 const char* name,
522 unsigned long long id,
523 int num_args,
524 const char** arg_names,
525 const unsigned char* arg_types,
526 const unsigned long long* arg_values,
527 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
528 unsigned char flags) {
529 timestamp_ = timestamp;
530 thread_timestamp_ = thread_timestamp;
531 duration_ = TimeDelta::FromInternalValue(-1);
532 id_ = id;
533 category_group_enabled_ = category_group_enabled;
534 name_ = name;
535 thread_id_ = thread_id;
536 phase_ = phase;
537 flags_ = flags;
538
539 // Clamp num_args since it may have been set by a third_party library.
540 num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
541 int i = 0;
542 for (; i < num_args; ++i) {
543 arg_names_[i] = arg_names[i];
544 arg_types_[i] = arg_types[i];
545
546 if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE)
547 convertable_values_[i] = convertable_values[i];
548 else
549 arg_values_[i].as_uint = arg_values[i];
550 }
551 for (; i < kTraceMaxNumArgs; ++i) {
552 arg_names_[i] = NULL;
553 arg_values_[i].as_uint = 0u;
554 convertable_values_[i] = NULL;
555 arg_types_[i] = TRACE_VALUE_TYPE_UINT;
556 }
557
558 bool copy = !!(flags & TRACE_EVENT_FLAG_COPY);
559 size_t alloc_size = 0;
560 if (copy) {
561 alloc_size += GetAllocLength(name);
562 for (i = 0; i < num_args; ++i) {
563 alloc_size += GetAllocLength(arg_names_[i]);
564 if (arg_types_[i] == TRACE_VALUE_TYPE_STRING)
565 arg_types_[i] = TRACE_VALUE_TYPE_COPY_STRING;
566 }
567 }
568
569 bool arg_is_copy[kTraceMaxNumArgs];
570 for (i = 0; i < num_args; ++i) {
571 // No copying of convertable types, we retain ownership.
572 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
573 continue;
574
575 // We only take a copy of arg_vals if they are of type COPY_STRING.
576 arg_is_copy[i] = (arg_types_[i] == TRACE_VALUE_TYPE_COPY_STRING);
577 if (arg_is_copy[i])
578 alloc_size += GetAllocLength(arg_values_[i].as_string);
579 }
580
581 if (alloc_size) {
582 parameter_copy_storage_ = new RefCountedString;
583 parameter_copy_storage_->data().resize(alloc_size);
584 char* ptr = string_as_array(¶meter_copy_storage_->data());
585 const char* end = ptr + alloc_size;
586 if (copy) {
587 CopyTraceEventParameter(&ptr, &name_, end);
588 for (i = 0; i < num_args; ++i) {
589 CopyTraceEventParameter(&ptr, &arg_names_[i], end);
590 }
591 }
592 for (i = 0; i < num_args; ++i) {
593 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
594 continue;
595 if (arg_is_copy[i])
596 CopyTraceEventParameter(&ptr, &arg_values_[i].as_string, end);
597 }
598 DCHECK_EQ(end, ptr) << "Overrun by " << ptr - end;
599 }
600 }
601
Reset()602 void TraceEvent::Reset() {
603 // Only reset fields that won't be initialized in Initialize(), or that may
604 // hold references to other objects.
605 duration_ = TimeDelta::FromInternalValue(-1);
606 parameter_copy_storage_ = NULL;
607 for (int i = 0; i < kTraceMaxNumArgs; ++i)
608 convertable_values_[i] = NULL;
609 }
610
UpdateDuration(const TimeTicks & now,const TimeTicks & thread_now)611 void TraceEvent::UpdateDuration(const TimeTicks& now,
612 const TimeTicks& thread_now) {
613 DCHECK(duration_.ToInternalValue() == -1);
614 duration_ = now - timestamp_;
615 thread_duration_ = thread_now - thread_timestamp_;
616 }
617
618 // static
AppendValueAsJSON(unsigned char type,TraceEvent::TraceValue value,std::string * out)619 void TraceEvent::AppendValueAsJSON(unsigned char type,
620 TraceEvent::TraceValue value,
621 std::string* out) {
622 switch (type) {
623 case TRACE_VALUE_TYPE_BOOL:
624 *out += value.as_bool ? "true" : "false";
625 break;
626 case TRACE_VALUE_TYPE_UINT:
627 StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
628 break;
629 case TRACE_VALUE_TYPE_INT:
630 StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
631 break;
632 case TRACE_VALUE_TYPE_DOUBLE: {
633 // FIXME: base/json/json_writer.cc is using the same code,
634 // should be made into a common method.
635 std::string real = DoubleToString(value.as_double);
636 // Ensure that the number has a .0 if there's no decimal or 'e'. This
637 // makes sure that when we read the JSON back, it's interpreted as a
638 // real rather than an int.
639 if (real.find('.') == std::string::npos &&
640 real.find('e') == std::string::npos &&
641 real.find('E') == std::string::npos) {
642 real.append(".0");
643 }
644 // The JSON spec requires that non-integer values in the range (-1,1)
645 // have a zero before the decimal point - ".52" is not valid, "0.52" is.
646 if (real[0] == '.') {
647 real.insert(0, "0");
648 } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
649 // "-.1" bad "-0.1" good
650 real.insert(1, "0");
651 }
652
653 StringAppendF(out, "%s", real.c_str());
654 break;
655 }
656 case TRACE_VALUE_TYPE_POINTER:
657 // JSON only supports double and int numbers.
658 // So as not to lose bits from a 64-bit pointer, output as a hex string.
659 StringAppendF(out, "\"0x%" PRIx64 "\"", static_cast<uint64>(
660 reinterpret_cast<intptr_t>(
661 value.as_pointer)));
662 break;
663 case TRACE_VALUE_TYPE_STRING:
664 case TRACE_VALUE_TYPE_COPY_STRING:
665 EscapeJSONString(value.as_string ? value.as_string : "NULL", true, out);
666 break;
667 default:
668 NOTREACHED() << "Don't know how to print this value";
669 break;
670 }
671 }
672
AppendAsJSON(std::string * out) const673 void TraceEvent::AppendAsJSON(std::string* out) const {
674 int64 time_int64 = timestamp_.ToInternalValue();
675 int process_id = TraceLog::GetInstance()->process_id();
676 // Category group checked at category creation time.
677 DCHECK(!strchr(name_, '"'));
678 StringAppendF(out,
679 "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ","
680 "\"ph\":\"%c\",\"name\":\"%s\",\"args\":{",
681 TraceLog::GetCategoryGroupName(category_group_enabled_),
682 process_id,
683 thread_id_,
684 time_int64,
685 phase_,
686 name_);
687
688 // Output argument names and values, stop at first NULL argument name.
689 for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
690 if (i > 0)
691 *out += ",";
692 *out += "\"";
693 *out += arg_names_[i];
694 *out += "\":";
695
696 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
697 convertable_values_[i]->AppendAsTraceFormat(out);
698 else
699 AppendValueAsJSON(arg_types_[i], arg_values_[i], out);
700 }
701 *out += "}";
702
703 if (phase_ == TRACE_EVENT_PHASE_COMPLETE) {
704 int64 duration = duration_.ToInternalValue();
705 if (duration != -1)
706 StringAppendF(out, ",\"dur\":%" PRId64, duration);
707 if (!thread_timestamp_.is_null()) {
708 int64 thread_duration = thread_duration_.ToInternalValue();
709 if (thread_duration != -1)
710 StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
711 }
712 }
713
714 // Output tts if thread_timestamp is valid.
715 if (!thread_timestamp_.is_null()) {
716 int64 thread_time_int64 = thread_timestamp_.ToInternalValue();
717 StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
718 }
719
720 // If id_ is set, print it out as a hex string so we don't loose any
721 // bits (it might be a 64-bit pointer).
722 if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
723 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
724
725 // Instant events also output their scope.
726 if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
727 char scope = '?';
728 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
729 case TRACE_EVENT_SCOPE_GLOBAL:
730 scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
731 break;
732
733 case TRACE_EVENT_SCOPE_PROCESS:
734 scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
735 break;
736
737 case TRACE_EVENT_SCOPE_THREAD:
738 scope = TRACE_EVENT_SCOPE_NAME_THREAD;
739 break;
740 }
741 StringAppendF(out, ",\"s\":\"%c\"", scope);
742 }
743
744 *out += "}";
745 }
746
AppendPrettyPrinted(std::ostringstream * out) const747 void TraceEvent::AppendPrettyPrinted(std::ostringstream* out) const {
748 *out << name_ << "[";
749 *out << TraceLog::GetCategoryGroupName(category_group_enabled_);
750 *out << "]";
751 if (arg_names_[0]) {
752 *out << ", {";
753 for (int i = 0; i < kTraceMaxNumArgs && arg_names_[i]; ++i) {
754 if (i > 0)
755 *out << ", ";
756 *out << arg_names_[i] << ":";
757 std::string value_as_text;
758
759 if (arg_types_[i] == TRACE_VALUE_TYPE_CONVERTABLE)
760 convertable_values_[i]->AppendAsTraceFormat(&value_as_text);
761 else
762 AppendValueAsJSON(arg_types_[i], arg_values_[i], &value_as_text);
763
764 *out << value_as_text;
765 }
766 *out << "}";
767 }
768 }
769
770 ////////////////////////////////////////////////////////////////////////////////
771 //
772 // TraceResultBuffer
773 //
774 ////////////////////////////////////////////////////////////////////////////////
775
776 TraceResultBuffer::OutputCallback
GetCallback()777 TraceResultBuffer::SimpleOutput::GetCallback() {
778 return Bind(&SimpleOutput::Append, Unretained(this));
779 }
780
Append(const std::string & json_trace_output)781 void TraceResultBuffer::SimpleOutput::Append(
782 const std::string& json_trace_output) {
783 json_output += json_trace_output;
784 }
785
TraceResultBuffer()786 TraceResultBuffer::TraceResultBuffer() : append_comma_(false) {
787 }
788
~TraceResultBuffer()789 TraceResultBuffer::~TraceResultBuffer() {
790 }
791
SetOutputCallback(const OutputCallback & json_chunk_callback)792 void TraceResultBuffer::SetOutputCallback(
793 const OutputCallback& json_chunk_callback) {
794 output_callback_ = json_chunk_callback;
795 }
796
Start()797 void TraceResultBuffer::Start() {
798 append_comma_ = false;
799 output_callback_.Run("[");
800 }
801
AddFragment(const std::string & trace_fragment)802 void TraceResultBuffer::AddFragment(const std::string& trace_fragment) {
803 if (append_comma_)
804 output_callback_.Run(",");
805 append_comma_ = true;
806 output_callback_.Run(trace_fragment);
807 }
808
Finish()809 void TraceResultBuffer::Finish() {
810 output_callback_.Run("]");
811 }
812
813 ////////////////////////////////////////////////////////////////////////////////
814 //
815 // TraceSamplingThread
816 //
817 ////////////////////////////////////////////////////////////////////////////////
818 class TraceBucketData;
819 typedef base::Callback<void(TraceBucketData*)> TraceSampleCallback;
820
821 class TraceBucketData {
822 public:
823 TraceBucketData(base::subtle::AtomicWord* bucket,
824 const char* name,
825 TraceSampleCallback callback);
826 ~TraceBucketData();
827
828 TRACE_EVENT_API_ATOMIC_WORD* bucket;
829 const char* bucket_name;
830 TraceSampleCallback callback;
831 };
832
833 // This object must be created on the IO thread.
834 class TraceSamplingThread : public PlatformThread::Delegate {
835 public:
836 TraceSamplingThread();
837 virtual ~TraceSamplingThread();
838
839 // Implementation of PlatformThread::Delegate:
840 virtual void ThreadMain() OVERRIDE;
841
842 static void DefaultSamplingCallback(TraceBucketData* bucekt_data);
843
844 void Stop();
845 void WaitSamplingEventForTesting();
846
847 private:
848 friend class TraceLog;
849
850 void GetSamples();
851 // Not thread-safe. Once the ThreadMain has been called, this can no longer
852 // be called.
853 void RegisterSampleBucket(TRACE_EVENT_API_ATOMIC_WORD* bucket,
854 const char* const name,
855 TraceSampleCallback callback);
856 // Splits a combined "category\0name" into the two component parts.
857 static void ExtractCategoryAndName(const char* combined,
858 const char** category,
859 const char** name);
860 std::vector<TraceBucketData> sample_buckets_;
861 bool thread_running_;
862 CancellationFlag cancellation_flag_;
863 WaitableEvent waitable_event_for_testing_;
864 };
865
866
TraceSamplingThread()867 TraceSamplingThread::TraceSamplingThread()
868 : thread_running_(false),
869 waitable_event_for_testing_(false, false) {
870 }
871
~TraceSamplingThread()872 TraceSamplingThread::~TraceSamplingThread() {
873 }
874
ThreadMain()875 void TraceSamplingThread::ThreadMain() {
876 PlatformThread::SetName("Sampling Thread");
877 thread_running_ = true;
878 const int kSamplingFrequencyMicroseconds = 1000;
879 while (!cancellation_flag_.IsSet()) {
880 PlatformThread::Sleep(
881 TimeDelta::FromMicroseconds(kSamplingFrequencyMicroseconds));
882 GetSamples();
883 waitable_event_for_testing_.Signal();
884 }
885 }
886
887 // static
DefaultSamplingCallback(TraceBucketData * bucket_data)888 void TraceSamplingThread::DefaultSamplingCallback(
889 TraceBucketData* bucket_data) {
890 TRACE_EVENT_API_ATOMIC_WORD category_and_name =
891 TRACE_EVENT_API_ATOMIC_LOAD(*bucket_data->bucket);
892 if (!category_and_name)
893 return;
894 const char* const combined =
895 reinterpret_cast<const char* const>(category_and_name);
896 const char* category_group;
897 const char* name;
898 ExtractCategoryAndName(combined, &category_group, &name);
899 TRACE_EVENT_API_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_SAMPLE,
900 TraceLog::GetCategoryGroupEnabled(category_group),
901 name, 0, 0, NULL, NULL, NULL, NULL, 0);
902 }
903
GetSamples()904 void TraceSamplingThread::GetSamples() {
905 for (size_t i = 0; i < sample_buckets_.size(); ++i) {
906 TraceBucketData* bucket_data = &sample_buckets_[i];
907 bucket_data->callback.Run(bucket_data);
908 }
909 }
910
RegisterSampleBucket(TRACE_EVENT_API_ATOMIC_WORD * bucket,const char * const name,TraceSampleCallback callback)911 void TraceSamplingThread::RegisterSampleBucket(
912 TRACE_EVENT_API_ATOMIC_WORD* bucket,
913 const char* const name,
914 TraceSampleCallback callback) {
915 // Access to sample_buckets_ doesn't cause races with the sampling thread
916 // that uses the sample_buckets_, because it is guaranteed that
917 // RegisterSampleBucket is called before the sampling thread is created.
918 DCHECK(!thread_running_);
919 sample_buckets_.push_back(TraceBucketData(bucket, name, callback));
920 }
921
922 // static
ExtractCategoryAndName(const char * combined,const char ** category,const char ** name)923 void TraceSamplingThread::ExtractCategoryAndName(const char* combined,
924 const char** category,
925 const char** name) {
926 *category = combined;
927 *name = &combined[strlen(combined) + 1];
928 }
929
Stop()930 void TraceSamplingThread::Stop() {
931 cancellation_flag_.Set();
932 }
933
WaitSamplingEventForTesting()934 void TraceSamplingThread::WaitSamplingEventForTesting() {
935 waitable_event_for_testing_.Wait();
936 }
937
TraceBucketData(base::subtle::AtomicWord * bucket,const char * name,TraceSampleCallback callback)938 TraceBucketData::TraceBucketData(base::subtle::AtomicWord* bucket,
939 const char* name,
940 TraceSampleCallback callback)
941 : bucket(bucket),
942 bucket_name(name),
943 callback(callback) {
944 }
945
~TraceBucketData()946 TraceBucketData::~TraceBucketData() {
947 }
948
949 ////////////////////////////////////////////////////////////////////////////////
950 //
951 // TraceLog
952 //
953 ////////////////////////////////////////////////////////////////////////////////
954
955 class TraceLog::ThreadLocalEventBuffer
956 : public MessageLoop::DestructionObserver {
957 public:
958 ThreadLocalEventBuffer(TraceLog* trace_log);
959 virtual ~ThreadLocalEventBuffer();
960
961 TraceEvent* AddTraceEvent(TraceEventHandle* handle);
962
963 void ReportOverhead(const TimeTicks& event_timestamp,
964 const TimeTicks& event_thread_timestamp);
965
GetEventByHandle(TraceEventHandle handle)966 TraceEvent* GetEventByHandle(TraceEventHandle handle) {
967 if (!chunk_ || handle.chunk_seq != chunk_->seq() ||
968 handle.chunk_index != chunk_index_)
969 return NULL;
970
971 return chunk_->GetEventAt(handle.event_index);
972 }
973
generation() const974 int generation() const { return generation_; }
975
976 private:
977 // MessageLoop::DestructionObserver
978 virtual void WillDestroyCurrentMessageLoop() OVERRIDE;
979
980 void FlushWhileLocked();
981
CheckThisIsCurrentBuffer() const982 void CheckThisIsCurrentBuffer() const {
983 DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
984 }
985
986 // Since TraceLog is a leaky singleton, trace_log_ will always be valid
987 // as long as the thread exists.
988 TraceLog* trace_log_;
989 scoped_ptr<TraceBufferChunk> chunk_;
990 size_t chunk_index_;
991 int event_count_;
992 TimeDelta overhead_;
993 int generation_;
994
995 DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
996 };
997
ThreadLocalEventBuffer(TraceLog * trace_log)998 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
999 : trace_log_(trace_log),
1000 chunk_index_(0),
1001 event_count_(0),
1002 generation_(trace_log->generation()) {
1003 // ThreadLocalEventBuffer is created only if the thread has a message loop, so
1004 // the following message_loop won't be NULL.
1005 MessageLoop* message_loop = MessageLoop::current();
1006 message_loop->AddDestructionObserver(this);
1007
1008 AutoLock lock(trace_log->lock_);
1009 trace_log->thread_message_loops_.insert(message_loop);
1010 }
1011
~ThreadLocalEventBuffer()1012 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
1013 CheckThisIsCurrentBuffer();
1014 MessageLoop::current()->RemoveDestructionObserver(this);
1015
1016 // Zero event_count_ happens in either of the following cases:
1017 // - no event generated for the thread;
1018 // - the thread has no message loop;
1019 // - trace_event_overhead is disabled.
1020 if (event_count_) {
1021 InitializeMetadataEvent(AddTraceEvent(NULL),
1022 static_cast<int>(base::PlatformThread::CurrentId()),
1023 "overhead", "average_overhead",
1024 overhead_.InMillisecondsF() / event_count_);
1025 }
1026
1027 {
1028 AutoLock lock(trace_log_->lock_);
1029 FlushWhileLocked();
1030 trace_log_->thread_message_loops_.erase(MessageLoop::current());
1031 }
1032 trace_log_->thread_local_event_buffer_.Set(NULL);
1033 }
1034
AddTraceEvent(TraceEventHandle * handle)1035 TraceEvent* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
1036 TraceEventHandle* handle) {
1037 CheckThisIsCurrentBuffer();
1038
1039 if (chunk_ && chunk_->IsFull()) {
1040 AutoLock lock(trace_log_->lock_);
1041 FlushWhileLocked();
1042 chunk_.reset();
1043 }
1044 if (!chunk_) {
1045 AutoLock lock(trace_log_->lock_);
1046 chunk_ = trace_log_->logged_events_->GetChunk(&chunk_index_);
1047 trace_log_->CheckIfBufferIsFullWhileLocked();
1048 }
1049 if (!chunk_)
1050 return NULL;
1051
1052 size_t event_index;
1053 TraceEvent* trace_event = chunk_->AddTraceEvent(&event_index);
1054 if (trace_event && handle)
1055 MakeHandle(chunk_->seq(), chunk_index_, event_index, handle);
1056
1057 return trace_event;
1058 }
1059
ReportOverhead(const TimeTicks & event_timestamp,const TimeTicks & event_thread_timestamp)1060 void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
1061 const TimeTicks& event_timestamp,
1062 const TimeTicks& event_thread_timestamp) {
1063 if (!g_category_group_enabled[g_category_trace_event_overhead])
1064 return;
1065
1066 CheckThisIsCurrentBuffer();
1067
1068 event_count_++;
1069 TimeTicks thread_now = ThreadNow();
1070 TimeTicks now = trace_log_->OffsetNow();
1071 TimeDelta overhead = now - event_timestamp;
1072 if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
1073 TraceEvent* trace_event = AddTraceEvent(NULL);
1074 if (trace_event) {
1075 trace_event->Initialize(
1076 static_cast<int>(PlatformThread::CurrentId()),
1077 event_timestamp, event_thread_timestamp,
1078 TRACE_EVENT_PHASE_COMPLETE,
1079 &g_category_group_enabled[g_category_trace_event_overhead],
1080 "overhead", 0, 0, NULL, NULL, NULL, NULL, 0);
1081 trace_event->UpdateDuration(now, thread_now);
1082 }
1083 }
1084 overhead_ += overhead;
1085 }
1086
WillDestroyCurrentMessageLoop()1087 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
1088 delete this;
1089 }
1090
FlushWhileLocked()1091 void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
1092 if (!chunk_)
1093 return;
1094
1095 trace_log_->lock_.AssertAcquired();
1096 if (trace_log_->CheckGeneration(generation_)) {
1097 // Return the chunk to the buffer only if the generation matches,
1098 trace_log_->logged_events_->ReturnChunk(chunk_index_, chunk_.Pass());
1099 }
1100 // Otherwise this method may be called from the destructor, or TraceLog will
1101 // find the generation mismatch and delete this buffer soon.
1102 }
1103
1104 // static
GetInstance()1105 TraceLog* TraceLog::GetInstance() {
1106 return Singleton<TraceLog, LeakySingletonTraits<TraceLog> >::get();
1107 }
1108
TraceLog()1109 TraceLog::TraceLog()
1110 : enabled_(false),
1111 num_traces_recorded_(0),
1112 event_callback_(0),
1113 dispatching_to_observer_list_(false),
1114 process_sort_index_(0),
1115 process_id_hash_(0),
1116 process_id_(0),
1117 watch_category_(0),
1118 trace_options_(RECORD_UNTIL_FULL),
1119 sampling_thread_handle_(0),
1120 category_filter_(CategoryFilter::kDefaultCategoryFilterString),
1121 event_callback_category_filter_(
1122 CategoryFilter::kDefaultCategoryFilterString),
1123 thread_shared_chunk_index_(0),
1124 generation_(0) {
1125 // Trace is enabled or disabled on one thread while other threads are
1126 // accessing the enabled flag. We don't care whether edge-case events are
1127 // traced or not, so we allow races on the enabled flag to keep the trace
1128 // macros fast.
1129 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
1130 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
1131 // sizeof(g_category_group_enabled),
1132 // "trace_event category enabled");
1133 for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
1134 ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
1135 "trace_event category enabled");
1136 }
1137 #if defined(OS_NACL) // NaCl shouldn't expose the process id.
1138 SetProcessID(0);
1139 #else
1140 SetProcessID(static_cast<int>(GetCurrentProcId()));
1141
1142 // NaCl also shouldn't access the command line.
1143 if (CommandLine::InitializedForCurrentProcess() &&
1144 CommandLine::ForCurrentProcess()->HasSwitch(switches::kTraceToConsole)) {
1145 std::string filter = CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
1146 switches::kTraceToConsole);
1147 if (filter.empty()) {
1148 filter = kEchoToConsoleCategoryFilter;
1149 } else {
1150 filter.append(",");
1151 filter.append(kEchoToConsoleCategoryFilter);
1152 }
1153
1154 LOG(ERROR) << "Start " << switches::kTraceToConsole
1155 << " with CategoryFilter '" << filter << "'.";
1156 SetEnabled(CategoryFilter(filter), ECHO_TO_CONSOLE);
1157 }
1158 #endif
1159
1160 logged_events_.reset(CreateTraceBuffer());
1161 }
1162
~TraceLog()1163 TraceLog::~TraceLog() {
1164 }
1165
GetCategoryGroupEnabled(const char * category_group)1166 const unsigned char* TraceLog::GetCategoryGroupEnabled(
1167 const char* category_group) {
1168 TraceLog* tracelog = GetInstance();
1169 if (!tracelog) {
1170 DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
1171 return &g_category_group_enabled[g_category_already_shutdown];
1172 }
1173 return tracelog->GetCategoryGroupEnabledInternal(category_group);
1174 }
1175
GetCategoryGroupName(const unsigned char * category_group_enabled)1176 const char* TraceLog::GetCategoryGroupName(
1177 const unsigned char* category_group_enabled) {
1178 // Calculate the index of the category group by finding
1179 // category_group_enabled in g_category_group_enabled array.
1180 uintptr_t category_begin =
1181 reinterpret_cast<uintptr_t>(g_category_group_enabled);
1182 uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
1183 DCHECK(category_ptr >= category_begin &&
1184 category_ptr < reinterpret_cast<uintptr_t>(
1185 g_category_group_enabled + MAX_CATEGORY_GROUPS)) <<
1186 "out of bounds category pointer";
1187 uintptr_t category_index =
1188 (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
1189 return g_category_groups[category_index];
1190 }
1191
UpdateCategoryGroupEnabledFlag(int category_index)1192 void TraceLog::UpdateCategoryGroupEnabledFlag(int category_index) {
1193 unsigned char enabled_flag = 0;
1194 const char* category_group = g_category_groups[category_index];
1195 if (enabled_ && category_filter_.IsCategoryGroupEnabled(category_group))
1196 enabled_flag |= ENABLED_FOR_RECORDING;
1197 if (event_callback_ &&
1198 event_callback_category_filter_.IsCategoryGroupEnabled(category_group))
1199 enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
1200 g_category_group_enabled[category_index] = enabled_flag;
1201 }
1202
UpdateCategoryGroupEnabledFlags()1203 void TraceLog::UpdateCategoryGroupEnabledFlags() {
1204 for (int i = 0; i < g_category_index; i++)
1205 UpdateCategoryGroupEnabledFlag(i);
1206 }
1207
GetCategoryGroupEnabledInternal(const char * category_group)1208 const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
1209 const char* category_group) {
1210 DCHECK(!strchr(category_group, '"')) <<
1211 "Category groups may not contain double quote";
1212 AutoLock lock(lock_);
1213
1214 unsigned char* category_group_enabled = NULL;
1215 // Search for pre-existing category group.
1216 for (int i = 0; i < g_category_index; i++) {
1217 if (strcmp(g_category_groups[i], category_group) == 0) {
1218 category_group_enabled = &g_category_group_enabled[i];
1219 break;
1220 }
1221 }
1222
1223 if (!category_group_enabled) {
1224 // Create a new category group
1225 DCHECK(g_category_index < MAX_CATEGORY_GROUPS) <<
1226 "must increase MAX_CATEGORY_GROUPS";
1227 if (g_category_index < MAX_CATEGORY_GROUPS) {
1228 int new_index = g_category_index++;
1229 // Don't hold on to the category_group pointer, so that we can create
1230 // category groups with strings not known at compile time (this is
1231 // required by SetWatchEvent).
1232 const char* new_group = strdup(category_group);
1233 ANNOTATE_LEAKING_OBJECT_PTR(new_group);
1234 g_category_groups[new_index] = new_group;
1235 DCHECK(!g_category_group_enabled[new_index]);
1236 // Note that if both included and excluded patterns in the
1237 // CategoryFilter are empty, we exclude nothing,
1238 // thereby enabling this category group.
1239 UpdateCategoryGroupEnabledFlag(new_index);
1240 category_group_enabled = &g_category_group_enabled[new_index];
1241 } else {
1242 category_group_enabled =
1243 &g_category_group_enabled[g_category_categories_exhausted];
1244 }
1245 }
1246 return category_group_enabled;
1247 }
1248
GetKnownCategoryGroups(std::vector<std::string> * category_groups)1249 void TraceLog::GetKnownCategoryGroups(
1250 std::vector<std::string>* category_groups) {
1251 AutoLock lock(lock_);
1252 category_groups->push_back(
1253 g_category_groups[g_category_trace_event_overhead]);
1254 for (int i = g_num_builtin_categories; i < g_category_index; i++)
1255 category_groups->push_back(g_category_groups[i]);
1256 }
1257
SetEnabled(const CategoryFilter & category_filter,Options options)1258 void TraceLog::SetEnabled(const CategoryFilter& category_filter,
1259 Options options) {
1260 std::vector<EnabledStateObserver*> observer_list;
1261 {
1262 AutoLock lock(lock_);
1263
1264 // Can't enable tracing when Flush() is in progress.
1265 DCHECK(!flush_message_loop_proxy_.get());
1266
1267 Options old_options = trace_options();
1268
1269 if (enabled_) {
1270 if (options != old_options) {
1271 DLOG(ERROR) << "Attemting to re-enable tracing with a different "
1272 << "set of options.";
1273 }
1274
1275 category_filter_.Merge(category_filter);
1276 UpdateCategoryGroupEnabledFlags();
1277 return;
1278 }
1279
1280 if (dispatching_to_observer_list_) {
1281 DLOG(ERROR) <<
1282 "Cannot manipulate TraceLog::Enabled state from an observer.";
1283 return;
1284 }
1285
1286 enabled_ = true;
1287
1288 if (options != old_options) {
1289 subtle::NoBarrier_Store(&trace_options_, options);
1290 UseNextTraceBuffer();
1291 }
1292
1293 num_traces_recorded_++;
1294
1295 category_filter_ = CategoryFilter(category_filter);
1296 UpdateCategoryGroupEnabledFlags();
1297
1298 if ((options & ENABLE_SAMPLING) || (options & MONITOR_SAMPLING)) {
1299 sampling_thread_.reset(new TraceSamplingThread);
1300 sampling_thread_->RegisterSampleBucket(
1301 &g_trace_state[0],
1302 "bucket0",
1303 Bind(&TraceSamplingThread::DefaultSamplingCallback));
1304 sampling_thread_->RegisterSampleBucket(
1305 &g_trace_state[1],
1306 "bucket1",
1307 Bind(&TraceSamplingThread::DefaultSamplingCallback));
1308 sampling_thread_->RegisterSampleBucket(
1309 &g_trace_state[2],
1310 "bucket2",
1311 Bind(&TraceSamplingThread::DefaultSamplingCallback));
1312 if (!PlatformThread::Create(
1313 0, sampling_thread_.get(), &sampling_thread_handle_)) {
1314 DCHECK(false) << "failed to create thread";
1315 }
1316 }
1317
1318 dispatching_to_observer_list_ = true;
1319 observer_list = enabled_state_observer_list_;
1320 }
1321 // Notify observers outside the lock in case they trigger trace events.
1322 for (size_t i = 0; i < observer_list.size(); ++i)
1323 observer_list[i]->OnTraceLogEnabled();
1324
1325 {
1326 AutoLock lock(lock_);
1327 dispatching_to_observer_list_ = false;
1328 }
1329 }
1330
GetCurrentCategoryFilter()1331 CategoryFilter TraceLog::GetCurrentCategoryFilter() {
1332 AutoLock lock(lock_);
1333 return category_filter_;
1334 }
1335
SetDisabled()1336 void TraceLog::SetDisabled() {
1337 AutoLock lock(lock_);
1338 SetDisabledWhileLocked();
1339 }
1340
SetDisabledWhileLocked()1341 void TraceLog::SetDisabledWhileLocked() {
1342 lock_.AssertAcquired();
1343
1344 if (!enabled_)
1345 return;
1346
1347 if (dispatching_to_observer_list_) {
1348 DLOG(ERROR)
1349 << "Cannot manipulate TraceLog::Enabled state from an observer.";
1350 return;
1351 }
1352
1353 enabled_ = false;
1354
1355 if (sampling_thread_.get()) {
1356 // Stop the sampling thread.
1357 sampling_thread_->Stop();
1358 lock_.Release();
1359 PlatformThread::Join(sampling_thread_handle_);
1360 lock_.Acquire();
1361 sampling_thread_handle_ = PlatformThreadHandle();
1362 sampling_thread_.reset();
1363 }
1364
1365 category_filter_.Clear();
1366 subtle::NoBarrier_Store(&watch_category_, 0);
1367 watch_event_name_ = "";
1368 UpdateCategoryGroupEnabledFlags();
1369 AddMetadataEventsWhileLocked();
1370
1371 dispatching_to_observer_list_ = true;
1372 std::vector<EnabledStateObserver*> observer_list =
1373 enabled_state_observer_list_;
1374
1375 {
1376 // Dispatch to observers outside the lock in case the observer triggers a
1377 // trace event.
1378 AutoUnlock unlock(lock_);
1379 for (size_t i = 0; i < observer_list.size(); ++i)
1380 observer_list[i]->OnTraceLogDisabled();
1381 }
1382 dispatching_to_observer_list_ = false;
1383 }
1384
GetNumTracesRecorded()1385 int TraceLog::GetNumTracesRecorded() {
1386 AutoLock lock(lock_);
1387 if (!enabled_)
1388 return -1;
1389 return num_traces_recorded_;
1390 }
1391
AddEnabledStateObserver(EnabledStateObserver * listener)1392 void TraceLog::AddEnabledStateObserver(EnabledStateObserver* listener) {
1393 enabled_state_observer_list_.push_back(listener);
1394 }
1395
RemoveEnabledStateObserver(EnabledStateObserver * listener)1396 void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver* listener) {
1397 std::vector<EnabledStateObserver*>::iterator it =
1398 std::find(enabled_state_observer_list_.begin(),
1399 enabled_state_observer_list_.end(),
1400 listener);
1401 if (it != enabled_state_observer_list_.end())
1402 enabled_state_observer_list_.erase(it);
1403 }
1404
HasEnabledStateObserver(EnabledStateObserver * listener) const1405 bool TraceLog::HasEnabledStateObserver(EnabledStateObserver* listener) const {
1406 std::vector<EnabledStateObserver*>::const_iterator it =
1407 std::find(enabled_state_observer_list_.begin(),
1408 enabled_state_observer_list_.end(),
1409 listener);
1410 return it != enabled_state_observer_list_.end();
1411 }
1412
GetBufferPercentFull() const1413 float TraceLog::GetBufferPercentFull() const {
1414 AutoLock lock(lock_);
1415 return static_cast<float>(static_cast<double>(logged_events_->Size()) /
1416 logged_events_->Capacity());
1417 }
1418
BufferIsFull() const1419 bool TraceLog::BufferIsFull() const {
1420 AutoLock lock(lock_);
1421 return logged_events_->IsFull();
1422 }
1423
CreateTraceBuffer()1424 TraceBuffer* TraceLog::CreateTraceBuffer() {
1425 Options options = trace_options();
1426 if (options & RECORD_CONTINUOUSLY)
1427 return new TraceBufferRingBuffer(kTraceEventRingBufferChunks);
1428 else if (options & MONITOR_SAMPLING)
1429 return new TraceBufferRingBuffer(kMonitorTraceEventBufferChunks);
1430 else if (options & ECHO_TO_CONSOLE)
1431 return new TraceBufferRingBuffer(kEchoToConsoleTraceEventBufferChunks);
1432 return new TraceBufferVector();
1433 }
1434
AddEventToThreadSharedChunkWhileLocked(TraceEventHandle * handle,bool check_buffer_is_full)1435 TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
1436 TraceEventHandle* handle, bool check_buffer_is_full) {
1437 lock_.AssertAcquired();
1438
1439 if (thread_shared_chunk_ && thread_shared_chunk_->IsFull()) {
1440 logged_events_->ReturnChunk(thread_shared_chunk_index_,
1441 thread_shared_chunk_.Pass());
1442 }
1443
1444 if (!thread_shared_chunk_) {
1445 thread_shared_chunk_ = logged_events_->GetChunk(
1446 &thread_shared_chunk_index_);
1447 if (check_buffer_is_full)
1448 CheckIfBufferIsFullWhileLocked();
1449 }
1450 if (!thread_shared_chunk_)
1451 return NULL;
1452
1453 size_t event_index;
1454 TraceEvent* trace_event = thread_shared_chunk_->AddTraceEvent(&event_index);
1455 if (trace_event && handle) {
1456 MakeHandle(thread_shared_chunk_->seq(), thread_shared_chunk_index_,
1457 event_index, handle);
1458 }
1459 return trace_event;
1460 }
1461
CheckIfBufferIsFullWhileLocked()1462 void TraceLog::CheckIfBufferIsFullWhileLocked() {
1463 lock_.AssertAcquired();
1464 if (logged_events_->IsFull())
1465 SetDisabledWhileLocked();
1466 }
1467
SetEventCallbackEnabled(const CategoryFilter & category_filter,EventCallback cb)1468 void TraceLog::SetEventCallbackEnabled(const CategoryFilter& category_filter,
1469 EventCallback cb) {
1470 AutoLock lock(lock_);
1471 subtle::NoBarrier_Store(&event_callback_,
1472 reinterpret_cast<subtle::AtomicWord>(cb));
1473 event_callback_category_filter_ = category_filter;
1474 UpdateCategoryGroupEnabledFlags();
1475 };
1476
SetEventCallbackDisabled()1477 void TraceLog::SetEventCallbackDisabled() {
1478 AutoLock lock(lock_);
1479 subtle::NoBarrier_Store(&event_callback_, 0);
1480 UpdateCategoryGroupEnabledFlags();
1481 }
1482
1483 // Flush() works as the following:
1484 // 1. Flush() is called in threadA whose message loop is saved in
1485 // flush_message_loop_proxy_;
1486 // 2. If thread_message_loops_ is not empty, threadA posts task to each message
1487 // loop to flush the thread local buffers; otherwise finish the flush;
1488 // 3. FlushCurrentThread() deletes the thread local event buffer:
1489 // - The last batch of events of the thread are flushed into the main buffer;
1490 // - The message loop will be removed from thread_message_loops_;
1491 // If this is the last message loop, finish the flush;
1492 // 4. If any thread hasn't finish its flush in time, finish the flush.
Flush(const TraceLog::OutputCallback & cb)1493 void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
1494 if (IsEnabled()) {
1495 // Can't flush when tracing is enabled because otherwise PostTask would
1496 // - generate more trace events;
1497 // - deschedule the calling thread on some platforms causing inaccurate
1498 // timing of the trace events.
1499 scoped_refptr<RefCountedString> empty_result = new RefCountedString;
1500 if (!cb.is_null())
1501 cb.Run(empty_result, false);
1502 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
1503 return;
1504 }
1505
1506 int generation = this->generation();
1507 {
1508 AutoLock lock(lock_);
1509 DCHECK(!flush_message_loop_proxy_.get());
1510 flush_message_loop_proxy_ = MessageLoopProxy::current();
1511 DCHECK(!thread_message_loops_.size() || flush_message_loop_proxy_.get());
1512 flush_output_callback_ = cb;
1513
1514 if (thread_shared_chunk_) {
1515 logged_events_->ReturnChunk(thread_shared_chunk_index_,
1516 thread_shared_chunk_.Pass());
1517 }
1518
1519 if (thread_message_loops_.size()) {
1520 for (hash_set<MessageLoop*>::const_iterator it =
1521 thread_message_loops_.begin();
1522 it != thread_message_loops_.end(); ++it) {
1523 (*it)->PostTask(
1524 FROM_HERE,
1525 Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation));
1526 }
1527 flush_message_loop_proxy_->PostDelayedTask(
1528 FROM_HERE,
1529 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
1530 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
1531 return;
1532 }
1533 }
1534
1535 FinishFlush(generation);
1536 }
1537
ConvertTraceEventsToTraceFormat(scoped_ptr<TraceBuffer> logged_events,const TraceLog::OutputCallback & flush_output_callback)1538 void TraceLog::ConvertTraceEventsToTraceFormat(
1539 scoped_ptr<TraceBuffer> logged_events,
1540 const TraceLog::OutputCallback& flush_output_callback) {
1541
1542 if (flush_output_callback.is_null())
1543 return;
1544
1545 // The callback need to be called at least once even if there is no events
1546 // to let the caller know the completion of flush.
1547 bool has_more_events = true;
1548 do {
1549 scoped_refptr<RefCountedString> json_events_str_ptr =
1550 new RefCountedString();
1551
1552 for (size_t i = 0; i < kTraceEventBatchChunks; ++i) {
1553 const TraceBufferChunk* chunk = logged_events->NextChunk();
1554 if (!chunk) {
1555 has_more_events = false;
1556 break;
1557 }
1558 for (size_t j = 0; j < chunk->size(); ++j) {
1559 if (i > 0 || j > 0)
1560 json_events_str_ptr->data().append(",");
1561 chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()));
1562 }
1563 }
1564
1565 flush_output_callback.Run(json_events_str_ptr, has_more_events);
1566 } while (has_more_events);
1567 }
1568
FinishFlush(int generation)1569 void TraceLog::FinishFlush(int generation) {
1570 scoped_ptr<TraceBuffer> previous_logged_events;
1571 OutputCallback flush_output_callback;
1572
1573 if (!CheckGeneration(generation))
1574 return;
1575
1576 {
1577 AutoLock lock(lock_);
1578
1579 previous_logged_events.swap(logged_events_);
1580 UseNextTraceBuffer();
1581 thread_message_loops_.clear();
1582
1583 flush_message_loop_proxy_ = NULL;
1584 flush_output_callback = flush_output_callback_;
1585 flush_output_callback_.Reset();
1586 }
1587
1588 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1589 flush_output_callback);
1590 }
1591
1592 // Run in each thread holding a local event buffer.
FlushCurrentThread(int generation)1593 void TraceLog::FlushCurrentThread(int generation) {
1594 {
1595 AutoLock lock(lock_);
1596 if (!CheckGeneration(generation) || !flush_message_loop_proxy_) {
1597 // This is late. The corresponding flush has finished.
1598 return;
1599 }
1600 }
1601
1602 // This will flush the thread local buffer.
1603 delete thread_local_event_buffer_.Get();
1604
1605 AutoLock lock(lock_);
1606 if (!CheckGeneration(generation) || !flush_message_loop_proxy_ ||
1607 thread_message_loops_.size())
1608 return;
1609
1610 flush_message_loop_proxy_->PostTask(
1611 FROM_HERE,
1612 Bind(&TraceLog::FinishFlush, Unretained(this), generation));
1613 }
1614
OnFlushTimeout(int generation)1615 void TraceLog::OnFlushTimeout(int generation) {
1616 {
1617 AutoLock lock(lock_);
1618 if (!CheckGeneration(generation) || !flush_message_loop_proxy_) {
1619 // Flush has finished before timeout.
1620 return;
1621 }
1622
1623 LOG(WARNING) <<
1624 "The following threads haven't finished flush in time. "
1625 "If this happens stably for some thread, please call "
1626 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
1627 "the thread to avoid its trace events from being lost.";
1628 for (hash_set<MessageLoop*>::const_iterator it =
1629 thread_message_loops_.begin();
1630 it != thread_message_loops_.end(); ++it) {
1631 LOG(WARNING) << "Thread: " << (*it)->thread_name();
1632 }
1633 }
1634 FinishFlush(generation);
1635 }
1636
FlushButLeaveBufferIntact(const TraceLog::OutputCallback & flush_output_callback)1637 void TraceLog::FlushButLeaveBufferIntact(
1638 const TraceLog::OutputCallback& flush_output_callback) {
1639 scoped_ptr<TraceBuffer> previous_logged_events;
1640 {
1641 AutoLock lock(lock_);
1642 AddMetadataEventsWhileLocked();
1643 if (thread_shared_chunk_) {
1644 // Return the chunk to the main buffer to flush the sampling data.
1645 logged_events_->ReturnChunk(thread_shared_chunk_index_,
1646 thread_shared_chunk_.Pass());
1647 }
1648 previous_logged_events = logged_events_->CloneForIteration().Pass();
1649 } // release lock
1650
1651 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1652 flush_output_callback);
1653 }
1654
UseNextTraceBuffer()1655 void TraceLog::UseNextTraceBuffer() {
1656 logged_events_.reset(CreateTraceBuffer());
1657 subtle::NoBarrier_AtomicIncrement(&generation_, 1);
1658 thread_shared_chunk_.reset();
1659 thread_shared_chunk_index_ = 0;
1660 }
1661
AddTraceEvent(char phase,const unsigned char * category_group_enabled,const char * name,unsigned long long 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 char flags)1662 TraceEventHandle TraceLog::AddTraceEvent(
1663 char phase,
1664 const unsigned char* category_group_enabled,
1665 const char* name,
1666 unsigned long long id,
1667 int num_args,
1668 const char** arg_names,
1669 const unsigned char* arg_types,
1670 const unsigned long long* arg_values,
1671 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1672 unsigned char flags) {
1673 int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1674 base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
1675 return AddTraceEventWithThreadIdAndTimestamp(phase, category_group_enabled,
1676 name, id, thread_id, now,
1677 num_args, arg_names,
1678 arg_types, arg_values,
1679 convertable_values, flags);
1680 }
1681
AddTraceEventWithThreadIdAndTimestamp(char phase,const unsigned char * category_group_enabled,const char * name,unsigned long long id,int thread_id,const TimeTicks & timestamp,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 char flags)1682 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1683 char phase,
1684 const unsigned char* category_group_enabled,
1685 const char* name,
1686 unsigned long long id,
1687 int thread_id,
1688 const TimeTicks& timestamp,
1689 int num_args,
1690 const char** arg_names,
1691 const unsigned char* arg_types,
1692 const unsigned long long* arg_values,
1693 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
1694 unsigned char flags) {
1695 TraceEventHandle handle = { 0, 0, 0 };
1696 if (!*category_group_enabled)
1697 return handle;
1698
1699 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1700 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1701 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1702 if (thread_is_in_trace_event_.Get())
1703 return handle;
1704
1705 AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
1706
1707 DCHECK(name);
1708
1709 if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
1710 id ^= process_id_hash_;
1711
1712 TimeTicks now = OffsetTimestamp(timestamp);
1713 TimeTicks thread_now = ThreadNow();
1714
1715 ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
1716 // A ThreadLocalEventBuffer needs the message loop
1717 // - to know when the thread exits;
1718 // - to handle the final flush.
1719 // For a thread without a message loop or the message loop may be blocked, the
1720 // trace events will be added into the main buffer directly.
1721 if (!thread_blocks_message_loop_.Get() && MessageLoop::current()) {
1722 thread_local_event_buffer = thread_local_event_buffer_.Get();
1723 if (thread_local_event_buffer &&
1724 !CheckGeneration(thread_local_event_buffer->generation())) {
1725 delete thread_local_event_buffer;
1726 thread_local_event_buffer = NULL;
1727 }
1728 if (!thread_local_event_buffer) {
1729 thread_local_event_buffer = new ThreadLocalEventBuffer(this);
1730 thread_local_event_buffer_.Set(thread_local_event_buffer);
1731 }
1732 }
1733
1734 // Check and update the current thread name only if the event is for the
1735 // current thread to avoid locks in most cases.
1736 if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
1737 const char* new_name = ThreadIdNameManager::GetInstance()->
1738 GetName(thread_id);
1739 // Check if the thread name has been set or changed since the previous
1740 // call (if any), but don't bother if the new name is empty. Note this will
1741 // not detect a thread name change within the same char* buffer address: we
1742 // favor common case performance over corner case correctness.
1743 if (new_name != g_current_thread_name.Get().Get() &&
1744 new_name && *new_name) {
1745 g_current_thread_name.Get().Set(new_name);
1746
1747 AutoLock thread_info_lock(thread_info_lock_);
1748
1749 hash_map<int, std::string>::iterator existing_name =
1750 thread_names_.find(thread_id);
1751 if (existing_name == thread_names_.end()) {
1752 // This is a new thread id, and a new name.
1753 thread_names_[thread_id] = new_name;
1754 } else {
1755 // This is a thread id that we've seen before, but potentially with a
1756 // new name.
1757 std::vector<StringPiece> existing_names;
1758 Tokenize(existing_name->second, ",", &existing_names);
1759 bool found = std::find(existing_names.begin(),
1760 existing_names.end(),
1761 new_name) != existing_names.end();
1762 if (!found) {
1763 if (existing_names.size())
1764 existing_name->second.push_back(',');
1765 existing_name->second.append(new_name);
1766 }
1767 }
1768 }
1769 }
1770
1771 std::string console_message;
1772 if ((*category_group_enabled & ENABLED_FOR_RECORDING)) {
1773 OptionalAutoLock lock(lock_);
1774
1775 TraceEvent* trace_event = NULL;
1776 if (thread_local_event_buffer) {
1777 trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
1778 } else {
1779 lock.EnsureAcquired();
1780 trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
1781 }
1782
1783 if (trace_event) {
1784 trace_event->Initialize(thread_id, now, thread_now, phase,
1785 category_group_enabled, name, id,
1786 num_args, arg_names, arg_types, arg_values,
1787 convertable_values, flags);
1788
1789 #if defined(OS_ANDROID)
1790 trace_event->SendToATrace();
1791 #endif
1792 }
1793
1794 if (trace_options() & ECHO_TO_CONSOLE) {
1795 console_message = EventToConsoleMessage(
1796 phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
1797 timestamp, trace_event);
1798 }
1799 }
1800
1801 if (console_message.size())
1802 LOG(ERROR) << console_message;
1803
1804 if (reinterpret_cast<const unsigned char*>(subtle::NoBarrier_Load(
1805 &watch_category_)) == category_group_enabled) {
1806 bool event_name_matches;
1807 WatchEventCallback watch_event_callback_copy;
1808 {
1809 AutoLock lock(lock_);
1810 event_name_matches = watch_event_name_ == name;
1811 watch_event_callback_copy = watch_event_callback_;
1812 }
1813 if (event_name_matches) {
1814 if (!watch_event_callback_copy.is_null())
1815 watch_event_callback_copy.Run();
1816 }
1817 }
1818
1819 if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
1820 EventCallback event_callback = reinterpret_cast<EventCallback>(
1821 subtle::NoBarrier_Load(&event_callback_));
1822 if (event_callback) {
1823 event_callback(now,
1824 phase == TRACE_EVENT_PHASE_COMPLETE ?
1825 TRACE_EVENT_PHASE_BEGIN : phase,
1826 category_group_enabled, name, id,
1827 num_args, arg_names, arg_types, arg_values,
1828 flags);
1829 }
1830 }
1831
1832 if (thread_local_event_buffer)
1833 thread_local_event_buffer->ReportOverhead(now, thread_now);
1834
1835 return handle;
1836 }
1837
1838 // May be called when a COMPELETE event ends and the unfinished event has been
1839 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
EventToConsoleMessage(unsigned char phase,const TimeTicks & timestamp,TraceEvent * trace_event)1840 std::string TraceLog::EventToConsoleMessage(unsigned char phase,
1841 const TimeTicks& timestamp,
1842 TraceEvent* trace_event) {
1843 AutoLock thread_info_lock(thread_info_lock_);
1844
1845 // The caller should translate TRACE_EVENT_PHASE_COMPLETE to
1846 // TRACE_EVENT_PHASE_BEGIN or TRACE_EVENT_END.
1847 DCHECK(phase != TRACE_EVENT_PHASE_COMPLETE);
1848
1849 TimeDelta duration;
1850 int thread_id = trace_event ?
1851 trace_event->thread_id() : PlatformThread::CurrentId();
1852 if (phase == TRACE_EVENT_PHASE_END) {
1853 duration = timestamp - thread_event_start_times_[thread_id].top();
1854 thread_event_start_times_[thread_id].pop();
1855 }
1856
1857 std::string thread_name = thread_names_[thread_id];
1858 if (thread_colors_.find(thread_name) == thread_colors_.end())
1859 thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;
1860
1861 std::ostringstream log;
1862 log << base::StringPrintf("%s: \x1b[0;3%dm",
1863 thread_name.c_str(),
1864 thread_colors_[thread_name]);
1865
1866 size_t depth = 0;
1867 if (thread_event_start_times_.find(thread_id) !=
1868 thread_event_start_times_.end())
1869 depth = thread_event_start_times_[thread_id].size();
1870
1871 for (size_t i = 0; i < depth; ++i)
1872 log << "| ";
1873
1874 if (trace_event)
1875 trace_event->AppendPrettyPrinted(&log);
1876 if (phase == TRACE_EVENT_PHASE_END)
1877 log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
1878
1879 log << "\x1b[0;m";
1880
1881 if (phase == TRACE_EVENT_PHASE_BEGIN)
1882 thread_event_start_times_[thread_id].push(timestamp);
1883
1884 return log.str();
1885 }
1886
AddTraceEventEtw(char phase,const char * name,const void * id,const char * extra)1887 void TraceLog::AddTraceEventEtw(char phase,
1888 const char* name,
1889 const void* id,
1890 const char* extra) {
1891 #if defined(OS_WIN)
1892 TraceEventETWProvider::Trace(name, phase, id, extra);
1893 #endif
1894 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
1895 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
1896 }
1897
AddTraceEventEtw(char phase,const char * name,const void * id,const std::string & extra)1898 void TraceLog::AddTraceEventEtw(char phase,
1899 const char* name,
1900 const void* id,
1901 const std::string& extra)
1902 {
1903 #if defined(OS_WIN)
1904 TraceEventETWProvider::Trace(name, phase, id, extra);
1905 #endif
1906 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
1907 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
1908 }
1909
UpdateTraceEventDuration(const unsigned char * category_group_enabled,const char * name,TraceEventHandle handle)1910 void TraceLog::UpdateTraceEventDuration(
1911 const unsigned char* category_group_enabled,
1912 const char* name,
1913 TraceEventHandle handle) {
1914 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1915 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1916 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1917 if (thread_is_in_trace_event_.Get())
1918 return;
1919
1920 AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
1921
1922 TimeTicks thread_now = ThreadNow();
1923 TimeTicks now = OffsetNow();
1924
1925 std::string console_message;
1926 if (*category_group_enabled & ENABLED_FOR_RECORDING) {
1927 OptionalAutoLock lock(lock_);
1928
1929 TraceEvent* trace_event = GetEventByHandleInternal(handle, &lock);
1930 if (trace_event) {
1931 DCHECK(trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE);
1932 trace_event->UpdateDuration(now, thread_now);
1933 #if defined(OS_ANDROID)
1934 trace_event->SendToATrace();
1935 #endif
1936 }
1937
1938 if (trace_options() & ECHO_TO_CONSOLE) {
1939 console_message = EventToConsoleMessage(TRACE_EVENT_PHASE_END,
1940 now, trace_event);
1941 }
1942 }
1943
1944 if (console_message.size())
1945 LOG(ERROR) << console_message;
1946
1947 if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
1948 EventCallback event_callback = reinterpret_cast<EventCallback>(
1949 subtle::NoBarrier_Load(&event_callback_));
1950 if (event_callback) {
1951 event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
1952 trace_event_internal::kNoEventId, 0, NULL, NULL, NULL,
1953 TRACE_EVENT_FLAG_NONE);
1954 }
1955 }
1956 }
1957
SetWatchEvent(const std::string & category_name,const std::string & event_name,const WatchEventCallback & callback)1958 void TraceLog::SetWatchEvent(const std::string& category_name,
1959 const std::string& event_name,
1960 const WatchEventCallback& callback) {
1961 const unsigned char* category = GetCategoryGroupEnabled(
1962 category_name.c_str());
1963 AutoLock lock(lock_);
1964 subtle::NoBarrier_Store(&watch_category_,
1965 reinterpret_cast<subtle::AtomicWord>(category));
1966 watch_event_name_ = event_name;
1967 watch_event_callback_ = callback;
1968 }
1969
CancelWatchEvent()1970 void TraceLog::CancelWatchEvent() {
1971 AutoLock lock(lock_);
1972 subtle::NoBarrier_Store(&watch_category_, 0);
1973 watch_event_name_ = "";
1974 watch_event_callback_.Reset();
1975 }
1976
AddMetadataEventsWhileLocked()1977 void TraceLog::AddMetadataEventsWhileLocked() {
1978 lock_.AssertAcquired();
1979
1980 int current_thread_id = static_cast<int>(base::PlatformThread::CurrentId());
1981 if (process_sort_index_ != 0) {
1982 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1983 current_thread_id,
1984 "process_sort_index", "sort_index",
1985 process_sort_index_);
1986 }
1987
1988 if (process_name_.size()) {
1989 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
1990 current_thread_id,
1991 "process_name", "name",
1992 process_name_);
1993 }
1994
1995 if (process_labels_.size() > 0) {
1996 std::vector<std::string> labels;
1997 for(base::hash_map<int, std::string>::iterator it = process_labels_.begin();
1998 it != process_labels_.end();
1999 it++) {
2000 labels.push_back(it->second);
2001 }
2002 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2003 current_thread_id,
2004 "process_labels", "labels",
2005 JoinString(labels, ','));
2006 }
2007
2008 // Thread sort indices.
2009 for(hash_map<int, int>::iterator it = thread_sort_indices_.begin();
2010 it != thread_sort_indices_.end();
2011 it++) {
2012 if (it->second == 0)
2013 continue;
2014 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2015 it->first,
2016 "thread_sort_index", "sort_index",
2017 it->second);
2018 }
2019
2020 // Thread names.
2021 AutoLock thread_info_lock(thread_info_lock_);
2022 for(hash_map<int, std::string>::iterator it = thread_names_.begin();
2023 it != thread_names_.end();
2024 it++) {
2025 if (it->second.empty())
2026 continue;
2027 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
2028 it->first,
2029 "thread_name", "name",
2030 it->second);
2031 }
2032 }
2033
WaitSamplingEventForTesting()2034 void TraceLog::WaitSamplingEventForTesting() {
2035 if (!sampling_thread_)
2036 return;
2037 sampling_thread_->WaitSamplingEventForTesting();
2038 }
2039
DeleteForTesting()2040 void TraceLog::DeleteForTesting() {
2041 DeleteTraceLogForTesting::Delete();
2042 }
2043
GetEventByHandle(TraceEventHandle handle)2044 TraceEvent* TraceLog::GetEventByHandle(TraceEventHandle handle) {
2045 return GetEventByHandleInternal(handle, NULL);
2046 }
2047
GetEventByHandleInternal(TraceEventHandle handle,OptionalAutoLock * lock)2048 TraceEvent* TraceLog::GetEventByHandleInternal(TraceEventHandle handle,
2049 OptionalAutoLock* lock) {
2050 if (!handle.chunk_seq)
2051 return NULL;
2052
2053 if (thread_local_event_buffer_.Get()) {
2054 TraceEvent* trace_event =
2055 thread_local_event_buffer_.Get()->GetEventByHandle(handle);
2056 if (trace_event)
2057 return trace_event;
2058 }
2059
2060 // The event has been out-of-control of the thread local buffer.
2061 // Try to get the event from the main buffer with a lock.
2062 if (lock)
2063 lock->EnsureAcquired();
2064
2065 if (thread_shared_chunk_ &&
2066 handle.chunk_index == thread_shared_chunk_index_) {
2067 return handle.chunk_seq == thread_shared_chunk_->seq() ?
2068 thread_shared_chunk_->GetEventAt(handle.event_index) : NULL;
2069 }
2070
2071 return logged_events_->GetEventByHandle(handle);
2072 }
2073
SetProcessID(int process_id)2074 void TraceLog::SetProcessID(int process_id) {
2075 process_id_ = process_id;
2076 // Create a FNV hash from the process ID for XORing.
2077 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
2078 unsigned long long offset_basis = 14695981039346656037ull;
2079 unsigned long long fnv_prime = 1099511628211ull;
2080 unsigned long long pid = static_cast<unsigned long long>(process_id_);
2081 process_id_hash_ = (offset_basis ^ pid) * fnv_prime;
2082 }
2083
SetProcessSortIndex(int sort_index)2084 void TraceLog::SetProcessSortIndex(int sort_index) {
2085 AutoLock lock(lock_);
2086 process_sort_index_ = sort_index;
2087 }
2088
SetProcessName(const std::string & process_name)2089 void TraceLog::SetProcessName(const std::string& process_name) {
2090 AutoLock lock(lock_);
2091 process_name_ = process_name;
2092 }
2093
UpdateProcessLabel(int label_id,const std::string & current_label)2094 void TraceLog::UpdateProcessLabel(
2095 int label_id, const std::string& current_label) {
2096 if(!current_label.length())
2097 return RemoveProcessLabel(label_id);
2098
2099 AutoLock lock(lock_);
2100 process_labels_[label_id] = current_label;
2101 }
2102
RemoveProcessLabel(int label_id)2103 void TraceLog::RemoveProcessLabel(int label_id) {
2104 AutoLock lock(lock_);
2105 base::hash_map<int, std::string>::iterator it = process_labels_.find(
2106 label_id);
2107 if (it == process_labels_.end())
2108 return;
2109
2110 process_labels_.erase(it);
2111 }
2112
SetThreadSortIndex(PlatformThreadId thread_id,int sort_index)2113 void TraceLog::SetThreadSortIndex(PlatformThreadId thread_id, int sort_index) {
2114 AutoLock lock(lock_);
2115 thread_sort_indices_[static_cast<int>(thread_id)] = sort_index;
2116 }
2117
SetTimeOffset(TimeDelta offset)2118 void TraceLog::SetTimeOffset(TimeDelta offset) {
2119 time_offset_ = offset;
2120 }
2121
GetObserverCountForTest() const2122 size_t TraceLog::GetObserverCountForTest() const {
2123 return enabled_state_observer_list_.size();
2124 }
2125
SetCurrentThreadBlocksMessageLoop()2126 void TraceLog::SetCurrentThreadBlocksMessageLoop() {
2127 thread_blocks_message_loop_.Set(true);
2128 if (thread_local_event_buffer_.Get()) {
2129 // This will flush the thread local buffer.
2130 delete thread_local_event_buffer_.Get();
2131 }
2132 }
2133
IsEmptyOrContainsLeadingOrTrailingWhitespace(const std::string & str)2134 bool CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2135 const std::string& str) {
2136 return str.empty() ||
2137 str.at(0) == ' ' ||
2138 str.at(str.length() - 1) == ' ';
2139 }
2140
DoesCategoryGroupContainCategory(const char * category_group,const char * category) const2141 bool CategoryFilter::DoesCategoryGroupContainCategory(
2142 const char* category_group,
2143 const char* category) const {
2144 DCHECK(category);
2145 CStringTokenizer category_group_tokens(category_group,
2146 category_group + strlen(category_group), ",");
2147 while (category_group_tokens.GetNext()) {
2148 std::string category_group_token = category_group_tokens.token();
2149 // Don't allow empty tokens, nor tokens with leading or trailing space.
2150 DCHECK(!CategoryFilter::IsEmptyOrContainsLeadingOrTrailingWhitespace(
2151 category_group_token))
2152 << "Disallowed category string";
2153 if (MatchPattern(category_group_token.c_str(), category))
2154 return true;
2155 }
2156 return false;
2157 }
2158
CategoryFilter(const std::string & filter_string)2159 CategoryFilter::CategoryFilter(const std::string& filter_string) {
2160 if (!filter_string.empty())
2161 Initialize(filter_string);
2162 else
2163 Initialize(CategoryFilter::kDefaultCategoryFilterString);
2164 }
2165
CategoryFilter(const CategoryFilter & cf)2166 CategoryFilter::CategoryFilter(const CategoryFilter& cf)
2167 : included_(cf.included_),
2168 disabled_(cf.disabled_),
2169 excluded_(cf.excluded_) {
2170 }
2171
~CategoryFilter()2172 CategoryFilter::~CategoryFilter() {
2173 }
2174
operator =(const CategoryFilter & rhs)2175 CategoryFilter& CategoryFilter::operator=(const CategoryFilter& rhs) {
2176 if (this == &rhs)
2177 return *this;
2178
2179 included_ = rhs.included_;
2180 disabled_ = rhs.disabled_;
2181 excluded_ = rhs.excluded_;
2182 return *this;
2183 }
2184
Initialize(const std::string & filter_string)2185 void CategoryFilter::Initialize(const std::string& filter_string) {
2186 // Tokenize list of categories, delimited by ','.
2187 StringTokenizer tokens(filter_string, ",");
2188 // Add each token to the appropriate list (included_,excluded_).
2189 while (tokens.GetNext()) {
2190 std::string category = tokens.token();
2191 // Ignore empty categories.
2192 if (category.empty())
2193 continue;
2194 // Excluded categories start with '-'.
2195 if (category.at(0) == '-') {
2196 // Remove '-' from category string.
2197 category = category.substr(1);
2198 excluded_.push_back(category);
2199 } else if (category.compare(0, strlen(TRACE_DISABLED_BY_DEFAULT("")),
2200 TRACE_DISABLED_BY_DEFAULT("")) == 0) {
2201 disabled_.push_back(category);
2202 } else {
2203 included_.push_back(category);
2204 }
2205 }
2206 }
2207
WriteString(const StringList & values,std::string * out,bool included) const2208 void CategoryFilter::WriteString(const StringList& values,
2209 std::string* out,
2210 bool included) const {
2211 bool prepend_comma = !out->empty();
2212 int token_cnt = 0;
2213 for (StringList::const_iterator ci = values.begin();
2214 ci != values.end(); ++ci) {
2215 if (token_cnt > 0 || prepend_comma)
2216 StringAppendF(out, ",");
2217 StringAppendF(out, "%s%s", (included ? "" : "-"), ci->c_str());
2218 ++token_cnt;
2219 }
2220 }
2221
ToString() const2222 std::string CategoryFilter::ToString() const {
2223 std::string filter_string;
2224 WriteString(included_, &filter_string, true);
2225 WriteString(disabled_, &filter_string, true);
2226 WriteString(excluded_, &filter_string, false);
2227 return filter_string;
2228 }
2229
IsCategoryGroupEnabled(const char * category_group_name) const2230 bool CategoryFilter::IsCategoryGroupEnabled(
2231 const char* category_group_name) const {
2232 // TraceLog should call this method only as part of enabling/disabling
2233 // categories.
2234 StringList::const_iterator ci;
2235
2236 // Check the disabled- filters and the disabled-* wildcard first so that a
2237 // "*" filter does not include the disabled.
2238 for (ci = disabled_.begin(); ci != disabled_.end(); ++ci) {
2239 if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2240 return true;
2241 }
2242 if (DoesCategoryGroupContainCategory(category_group_name,
2243 TRACE_DISABLED_BY_DEFAULT("*")))
2244 return false;
2245
2246 for (ci = included_.begin(); ci != included_.end(); ++ci) {
2247 if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2248 return true;
2249 }
2250
2251 for (ci = excluded_.begin(); ci != excluded_.end(); ++ci) {
2252 if (DoesCategoryGroupContainCategory(category_group_name, ci->c_str()))
2253 return false;
2254 }
2255 // If the category group is not excluded, and there are no included patterns
2256 // we consider this pattern enabled.
2257 return included_.empty();
2258 }
2259
HasIncludedPatterns() const2260 bool CategoryFilter::HasIncludedPatterns() const {
2261 return !included_.empty();
2262 }
2263
Merge(const CategoryFilter & nested_filter)2264 void CategoryFilter::Merge(const CategoryFilter& nested_filter) {
2265 // Keep included patterns only if both filters have an included entry.
2266 // Otherwise, one of the filter was specifying "*" and we want to honour the
2267 // broadest filter.
2268 if (HasIncludedPatterns() && nested_filter.HasIncludedPatterns()) {
2269 included_.insert(included_.end(),
2270 nested_filter.included_.begin(),
2271 nested_filter.included_.end());
2272 } else {
2273 included_.clear();
2274 }
2275
2276 disabled_.insert(disabled_.end(),
2277 nested_filter.disabled_.begin(),
2278 nested_filter.disabled_.end());
2279 excluded_.insert(excluded_.end(),
2280 nested_filter.excluded_.begin(),
2281 nested_filter.excluded_.end());
2282 }
2283
Clear()2284 void CategoryFilter::Clear() {
2285 included_.clear();
2286 disabled_.clear();
2287 excluded_.clear();
2288 }
2289
2290 } // namespace debug
2291 } // namespace base
2292
2293 namespace trace_event_internal {
2294
ScopedTraceBinaryEfficient(const char * category_group,const char * name)2295 ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
2296 const char* category_group, const char* name) {
2297 // The single atom works because for now the category_group can only be "gpu".
2298 DCHECK(strcmp(category_group, "gpu") == 0);
2299 static TRACE_EVENT_API_ATOMIC_WORD atomic = 0;
2300 INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
2301 category_group, atomic, category_group_enabled_);
2302 name_ = name;
2303 if (*category_group_enabled_) {
2304 event_handle_ =
2305 TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
2306 TRACE_EVENT_PHASE_COMPLETE, category_group_enabled_, name,
2307 trace_event_internal::kNoEventId,
2308 static_cast<int>(base::PlatformThread::CurrentId()),
2309 base::TimeTicks::NowFromSystemTraceTime(),
2310 0, NULL, NULL, NULL, NULL, TRACE_EVENT_FLAG_NONE);
2311 }
2312 }
2313
~ScopedTraceBinaryEfficient()2314 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
2315 if (*category_group_enabled_) {
2316 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
2317 name_, event_handle_);
2318 }
2319 }
2320
2321 } // namespace trace_event_internal
2322