1 // Copyright 2015 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.
5 #include "base/trace_event/trace_log.h"
10 #include "base/base_switches.h"
11 #include "base/bind.h"
12 #include "base/command_line.h"
13 #include "base/debug/leak_annotations.h"
14 #include "base/lazy_instance.h"
15 #include "base/location.h"
16 #include "base/memory/singleton.h"
17 #include "base/process/process_metrics.h"
18 #include "base/strings/string_split.h"
19 #include "base/strings/string_tokenizer.h"
20 #include "base/strings/stringprintf.h"
21 #include "base/sys_info.h"
22 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
23 #include "base/thread_task_runner_handle.h"
24 #include "base/threading/platform_thread.h"
25 #include "base/threading/thread_id_name_manager.h"
26 #include "base/threading/worker_pool.h"
27 #include "base/time/time.h"
28 #include "base/trace_event/memory_dump_manager.h"
29 #include "base/trace_event/memory_dump_provider.h"
30 #include "base/trace_event/process_memory_dump.h"
31 #include "base/trace_event/trace_buffer.h"
32 #include "base/trace_event/trace_event.h"
33 #include "base/trace_event/trace_event_synthetic_delay.h"
34 #include "base/trace_event/trace_log.h"
35 #include "base/trace_event/trace_sampling_thread.h"
38 #include "base/trace_event/trace_event_etw_export_win.h"
39 #include "base/trace_event/trace_event_win.h"
42 class DeleteTraceLogForTesting
{
44 static void Delete() {
45 Singleton
<base::trace_event::TraceLog
,
46 LeakySingletonTraits
<base::trace_event::TraceLog
>>::OnExit(0);
50 // The thread buckets for the sampling profiler.
51 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state
[3];
54 namespace trace_event
{
58 // Controls the number of trace events we will buffer in-memory
59 // before throwing them away.
60 const size_t kTraceBufferChunkSize
= TraceBufferChunk::kTraceBufferChunkSize
;
61 const size_t kTraceEventVectorBigBufferChunks
=
62 512000000 / kTraceBufferChunkSize
;
63 const size_t kTraceEventVectorBufferChunks
= 256000 / kTraceBufferChunkSize
;
64 const size_t kTraceEventRingBufferChunks
= kTraceEventVectorBufferChunks
/ 4;
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;
70 // The overhead of TraceEvent above this threshold will be reported in the
72 const int kOverheadReportThresholdInMicroseconds
= 50;
73 const size_t kTraceEventBufferSizeInBytes
= 100 * 1024;
74 const int kThreadFlushTimeoutMs
= 3000;
77 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
78 const char kEchoToConsoleCategoryFilter
[] = "-ipc,-task";
81 #define MAX_CATEGORY_GROUPS 100
83 // Parallel arrays g_category_groups and g_category_group_enabled are separate
84 // so that a pointer to a member of g_category_group_enabled can be easily
85 // converted to an index into g_category_groups. This allows macros to deal
86 // only with char enabled pointers from g_category_group_enabled, and we can
87 // convert internally to determine the category name from the char enabled
89 const char* g_category_groups
[MAX_CATEGORY_GROUPS
] = {
91 "tracing already shutdown",
92 "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
94 // For reporting trace_event overhead. For thread local event buffers only.
95 "trace_event_overhead"};
97 // The enabled flag is char instead of bool so that the API can be used from C.
98 unsigned char g_category_group_enabled
[MAX_CATEGORY_GROUPS
] = {0};
99 // Indexes here have to match the g_category_groups array indexes above.
100 const int g_category_already_shutdown
= 1;
101 const int g_category_categories_exhausted
= 2;
102 const int g_category_metadata
= 3;
103 const int g_category_trace_event_overhead
= 4;
104 const int g_num_builtin_categories
= 5;
105 // Skip default categories.
106 base::subtle::AtomicWord g_category_index
= g_num_builtin_categories
;
108 // The name of the current thread. This is used to decide if the current
109 // thread name has changed. We combine all the seen thread names into the
110 // output name for the thread.
111 LazyInstance
<ThreadLocalPointer
<const char>>::Leaky g_current_thread_name
=
112 LAZY_INSTANCE_INITIALIZER
;
114 ThreadTicks
ThreadNow() {
115 return ThreadTicks::IsSupported() ? ThreadTicks::Now() : ThreadTicks();
118 template <typename T
>
119 void InitializeMetadataEvent(TraceEvent
* trace_event
,
121 const char* metadata_name
,
122 const char* arg_name
,
128 unsigned char arg_type
;
129 unsigned long long arg_value
;
130 ::trace_event_internal::SetTraceValue(value
, &arg_type
, &arg_value
);
131 trace_event
->Initialize(
135 TRACE_EVENT_PHASE_METADATA
,
136 &g_category_group_enabled
[g_category_metadata
],
138 trace_event_internal::kNoId
, // id
139 trace_event_internal::kNoId
, // context_id
140 trace_event_internal::kNoId
, // bind_id
146 TRACE_EVENT_FLAG_NONE
);
149 class AutoThreadLocalBoolean
{
151 explicit AutoThreadLocalBoolean(ThreadLocalBoolean
* thread_local_boolean
)
152 : thread_local_boolean_(thread_local_boolean
) {
153 DCHECK(!thread_local_boolean_
->Get());
154 thread_local_boolean_
->Set(true);
156 ~AutoThreadLocalBoolean() { thread_local_boolean_
->Set(false); }
159 ThreadLocalBoolean
* thread_local_boolean_
;
160 DISALLOW_COPY_AND_ASSIGN(AutoThreadLocalBoolean
);
163 // Use this function instead of TraceEventHandle constructor to keep the
164 // overhead of ScopedTracer (trace_event.h) constructor minimum.
165 void MakeHandle(uint32 chunk_seq
,
168 TraceEventHandle
* handle
) {
170 DCHECK(chunk_index
< (1u << 16));
171 DCHECK(event_index
< (1u << 16));
172 handle
->chunk_seq
= chunk_seq
;
173 handle
->chunk_index
= static_cast<uint16
>(chunk_index
);
174 handle
->event_index
= static_cast<uint16
>(event_index
);
179 // A helper class that allows the lock to be acquired in the middle of the scope
180 // and unlocks at the end of scope if locked.
181 class TraceLog::OptionalAutoLock
{
183 explicit OptionalAutoLock(Lock
* lock
) : lock_(lock
), locked_(false) {}
185 ~OptionalAutoLock() {
190 void EnsureAcquired() {
200 DISALLOW_COPY_AND_ASSIGN(OptionalAutoLock
);
203 class TraceLog::ThreadLocalEventBuffer
204 : public MessageLoop::DestructionObserver
,
205 public MemoryDumpProvider
{
207 ThreadLocalEventBuffer(TraceLog
* trace_log
);
208 ~ThreadLocalEventBuffer() override
;
210 TraceEvent
* AddTraceEvent(TraceEventHandle
* handle
);
212 void ReportOverhead(const TraceTicks
& event_timestamp
,
213 const ThreadTicks
& event_thread_timestamp
);
215 TraceEvent
* GetEventByHandle(TraceEventHandle handle
) {
216 if (!chunk_
|| handle
.chunk_seq
!= chunk_
->seq() ||
217 handle
.chunk_index
!= chunk_index_
)
220 return chunk_
->GetEventAt(handle
.event_index
);
223 int generation() const { return generation_
; }
226 // MessageLoop::DestructionObserver
227 void WillDestroyCurrentMessageLoop() override
;
229 // MemoryDumpProvider implementation.
230 bool OnMemoryDump(const MemoryDumpArgs
& args
,
231 ProcessMemoryDump
* pmd
) override
;
233 void FlushWhileLocked();
235 void CheckThisIsCurrentBuffer() const {
236 DCHECK(trace_log_
->thread_local_event_buffer_
.Get() == this);
239 // Since TraceLog is a leaky singleton, trace_log_ will always be valid
240 // as long as the thread exists.
241 TraceLog
* trace_log_
;
242 scoped_ptr
<TraceBufferChunk
> chunk_
;
248 DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer
);
251 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog
* trace_log
)
252 : trace_log_(trace_log
),
255 generation_(trace_log
->generation()) {
256 // ThreadLocalEventBuffer is created only if the thread has a message loop, so
257 // the following message_loop won't be NULL.
258 MessageLoop
* message_loop
= MessageLoop::current();
259 message_loop
->AddDestructionObserver(this);
261 // This is to report the local memory usage when memory-infra is enabled.
262 MemoryDumpManager::GetInstance()->RegisterDumpProvider(
263 this, ThreadTaskRunnerHandle::Get());
265 AutoLock
lock(trace_log
->lock_
);
266 trace_log
->thread_message_loops_
.insert(message_loop
);
269 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
270 CheckThisIsCurrentBuffer();
271 MessageLoop::current()->RemoveDestructionObserver(this);
272 MemoryDumpManager::GetInstance()->UnregisterDumpProvider(this);
274 // Zero event_count_ happens in either of the following cases:
275 // - no event generated for the thread;
276 // - the thread has no message loop;
277 // - trace_event_overhead is disabled.
279 InitializeMetadataEvent(AddTraceEvent(NULL
),
280 static_cast<int>(base::PlatformThread::CurrentId()),
281 "overhead", "average_overhead",
282 overhead_
.InMillisecondsF() / event_count_
);
286 AutoLock
lock(trace_log_
->lock_
);
288 trace_log_
->thread_message_loops_
.erase(MessageLoop::current());
290 trace_log_
->thread_local_event_buffer_
.Set(NULL
);
293 TraceEvent
* TraceLog::ThreadLocalEventBuffer::AddTraceEvent(
294 TraceEventHandle
* handle
) {
295 CheckThisIsCurrentBuffer();
297 if (chunk_
&& chunk_
->IsFull()) {
298 AutoLock
lock(trace_log_
->lock_
);
303 AutoLock
lock(trace_log_
->lock_
);
304 chunk_
= trace_log_
->logged_events_
->GetChunk(&chunk_index_
);
305 trace_log_
->CheckIfBufferIsFullWhileLocked();
311 TraceEvent
* trace_event
= chunk_
->AddTraceEvent(&event_index
);
312 if (trace_event
&& handle
)
313 MakeHandle(chunk_
->seq(), chunk_index_
, event_index
, handle
);
318 void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
319 const TraceTicks
& event_timestamp
,
320 const ThreadTicks
& event_thread_timestamp
) {
321 if (!g_category_group_enabled
[g_category_trace_event_overhead
])
324 CheckThisIsCurrentBuffer();
327 ThreadTicks thread_now
= ThreadNow();
328 TraceTicks now
= trace_log_
->OffsetNow();
329 TimeDelta overhead
= now
- event_timestamp
;
330 if (overhead
.InMicroseconds() >= kOverheadReportThresholdInMicroseconds
) {
331 TraceEvent
* trace_event
= AddTraceEvent(NULL
);
333 trace_event
->Initialize(
334 static_cast<int>(PlatformThread::CurrentId()),
336 event_thread_timestamp
,
337 TRACE_EVENT_PHASE_COMPLETE
,
338 &g_category_group_enabled
[g_category_trace_event_overhead
],
340 trace_event_internal::kNoId
, // id
341 trace_event_internal::kNoId
, // context_id
342 trace_event_internal::kNoId
, // bind_id
343 ::trace_event_internal::kZeroNumArgs
,
348 TRACE_EVENT_FLAG_NONE
);
349 trace_event
->UpdateDuration(now
, thread_now
);
352 overhead_
+= overhead
;
355 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
359 bool TraceLog::ThreadLocalEventBuffer::OnMemoryDump(const MemoryDumpArgs
& args
,
360 ProcessMemoryDump
* pmd
) {
363 std::string dump_base_name
= StringPrintf(
364 "tracing/thread_%d", static_cast<int>(PlatformThread::CurrentId()));
365 TraceEventMemoryOverhead overhead
;
366 chunk_
->EstimateTraceMemoryOverhead(&overhead
);
367 overhead
.DumpInto(dump_base_name
.c_str(), pmd
);
371 void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
375 trace_log_
->lock_
.AssertAcquired();
376 if (trace_log_
->CheckGeneration(generation_
)) {
377 // Return the chunk to the buffer only if the generation matches.
378 trace_log_
->logged_events_
->ReturnChunk(chunk_index_
, chunk_
.Pass());
380 // Otherwise this method may be called from the destructor, or TraceLog will
381 // find the generation mismatch and delete this buffer soon.
384 TraceLogStatus::TraceLogStatus() : event_capacity(0), event_count(0) {}
386 TraceLogStatus::~TraceLogStatus() {}
389 TraceLog
* TraceLog::GetInstance() {
390 return Singleton
<TraceLog
, LeakySingletonTraits
<TraceLog
>>::get();
395 num_traces_recorded_(0),
397 dispatching_to_observer_list_(false),
398 process_sort_index_(0),
402 trace_options_(kInternalRecordUntilFull
),
403 sampling_thread_handle_(0),
404 trace_config_(TraceConfig()),
405 event_callback_trace_config_(TraceConfig()),
406 thread_shared_chunk_index_(0),
408 use_worker_thread_(false) {
409 // Trace is enabled or disabled on one thread while other threads are
410 // accessing the enabled flag. We don't care whether edge-case events are
411 // traced or not, so we allow races on the enabled flag to keep the trace
413 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
414 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
415 // sizeof(g_category_group_enabled),
416 // "trace_event category enabled");
417 for (int i
= 0; i
< MAX_CATEGORY_GROUPS
; ++i
) {
418 ANNOTATE_BENIGN_RACE(&g_category_group_enabled
[i
],
419 "trace_event category enabled");
421 #if defined(OS_NACL) // NaCl shouldn't expose the process id.
424 SetProcessID(static_cast<int>(GetCurrentProcId()));
426 // NaCl also shouldn't access the command line.
427 if (CommandLine::InitializedForCurrentProcess() &&
428 CommandLine::ForCurrentProcess()->HasSwitch(switches::kTraceToConsole
)) {
429 std::string filter
= CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
430 switches::kTraceToConsole
);
431 if (filter
.empty()) {
432 filter
= kEchoToConsoleCategoryFilter
;
435 filter
.append(kEchoToConsoleCategoryFilter
);
438 LOG(ERROR
) << "Start " << switches::kTraceToConsole
439 << " with CategoryFilter '" << filter
<< "'.";
440 SetEnabled(TraceConfig(filter
, ECHO_TO_CONSOLE
), RECORDING_MODE
);
444 logged_events_
.reset(CreateTraceBuffer());
446 MemoryDumpManager::GetInstance()->RegisterDumpProvider(this);
449 TraceLog::~TraceLog() {}
451 void TraceLog::InitializeThreadLocalEventBufferIfSupported() {
452 // A ThreadLocalEventBuffer needs the message loop
453 // - to know when the thread exits;
454 // - to handle the final flush.
455 // For a thread without a message loop or the message loop may be blocked, the
456 // trace events will be added into the main buffer directly.
457 if (thread_blocks_message_loop_
.Get() || !MessageLoop::current())
459 auto thread_local_event_buffer
= thread_local_event_buffer_
.Get();
460 if (thread_local_event_buffer
&&
461 !CheckGeneration(thread_local_event_buffer
->generation())) {
462 delete thread_local_event_buffer
;
463 thread_local_event_buffer
= NULL
;
465 if (!thread_local_event_buffer
) {
466 thread_local_event_buffer
= new ThreadLocalEventBuffer(this);
467 thread_local_event_buffer_
.Set(thread_local_event_buffer
);
471 bool TraceLog::OnMemoryDump(const MemoryDumpArgs
& args
,
472 ProcessMemoryDump
* pmd
) {
473 // TODO(ssid): Use MemoryDumpArgs to create light dumps when requested
474 // (crbug.com/499731).
475 TraceEventMemoryOverhead overhead
;
476 overhead
.Add("TraceLog", sizeof(*this));
478 AutoLock
lock(lock_
);
480 logged_events_
->EstimateTraceMemoryOverhead(&overhead
);
483 overhead
.DumpInto("tracing/main_trace_log", pmd
);
487 const unsigned char* TraceLog::GetCategoryGroupEnabled(
488 const char* category_group
) {
489 TraceLog
* tracelog
= GetInstance();
491 DCHECK(!g_category_group_enabled
[g_category_already_shutdown
]);
492 return &g_category_group_enabled
[g_category_already_shutdown
];
494 return tracelog
->GetCategoryGroupEnabledInternal(category_group
);
497 const char* TraceLog::GetCategoryGroupName(
498 const unsigned char* category_group_enabled
) {
499 // Calculate the index of the category group by finding
500 // category_group_enabled in g_category_group_enabled array.
501 uintptr_t category_begin
=
502 reinterpret_cast<uintptr_t>(g_category_group_enabled
);
503 uintptr_t category_ptr
= reinterpret_cast<uintptr_t>(category_group_enabled
);
504 DCHECK(category_ptr
>= category_begin
&&
505 category_ptr
< reinterpret_cast<uintptr_t>(g_category_group_enabled
+
506 MAX_CATEGORY_GROUPS
))
507 << "out of bounds category pointer";
508 uintptr_t category_index
=
509 (category_ptr
- category_begin
) / sizeof(g_category_group_enabled
[0]);
510 return g_category_groups
[category_index
];
513 void TraceLog::UpdateCategoryGroupEnabledFlag(size_t category_index
) {
514 unsigned char enabled_flag
= 0;
515 const char* category_group
= g_category_groups
[category_index
];
516 if (mode_
== RECORDING_MODE
&&
517 trace_config_
.IsCategoryGroupEnabled(category_group
))
518 enabled_flag
|= ENABLED_FOR_RECORDING
;
519 else if (mode_
== MONITORING_MODE
&&
520 trace_config_
.IsCategoryGroupEnabled(category_group
))
521 enabled_flag
|= ENABLED_FOR_MONITORING
;
522 if (event_callback_
&&
523 event_callback_trace_config_
.IsCategoryGroupEnabled(category_group
))
524 enabled_flag
|= ENABLED_FOR_EVENT_CALLBACK
;
526 if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
528 enabled_flag
|= ENABLED_FOR_ETW_EXPORT
;
532 g_category_group_enabled
[category_index
] = enabled_flag
;
535 void TraceLog::UpdateCategoryGroupEnabledFlags() {
536 size_t category_index
= base::subtle::NoBarrier_Load(&g_category_index
);
537 for (size_t i
= 0; i
< category_index
; i
++)
538 UpdateCategoryGroupEnabledFlag(i
);
541 void TraceLog::UpdateSyntheticDelaysFromTraceConfig() {
542 ResetTraceEventSyntheticDelays();
543 const TraceConfig::StringList
& delays
=
544 trace_config_
.GetSyntheticDelayValues();
545 TraceConfig::StringList::const_iterator ci
;
546 for (ci
= delays
.begin(); ci
!= delays
.end(); ++ci
) {
547 StringTokenizer
tokens(*ci
, ";");
548 if (!tokens
.GetNext())
550 TraceEventSyntheticDelay
* delay
=
551 TraceEventSyntheticDelay::Lookup(tokens
.token());
552 while (tokens
.GetNext()) {
553 std::string token
= tokens
.token();
555 double target_duration
= strtod(token
.c_str(), &duration_end
);
556 if (duration_end
!= token
.c_str()) {
557 delay
->SetTargetDuration(TimeDelta::FromMicroseconds(
558 static_cast<int64
>(target_duration
* 1e6
)));
559 } else if (token
== "static") {
560 delay
->SetMode(TraceEventSyntheticDelay::STATIC
);
561 } else if (token
== "oneshot") {
562 delay
->SetMode(TraceEventSyntheticDelay::ONE_SHOT
);
563 } else if (token
== "alternating") {
564 delay
->SetMode(TraceEventSyntheticDelay::ALTERNATING
);
570 const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
571 const char* category_group
) {
572 DCHECK(!strchr(category_group
, '"'))
573 << "Category groups may not contain double quote";
574 // The g_category_groups is append only, avoid using a lock for the fast path.
575 size_t current_category_index
= base::subtle::Acquire_Load(&g_category_index
);
577 // Search for pre-existing category group.
578 for (size_t i
= 0; i
< current_category_index
; ++i
) {
579 if (strcmp(g_category_groups
[i
], category_group
) == 0) {
580 return &g_category_group_enabled
[i
];
584 unsigned char* category_group_enabled
= NULL
;
585 // This is the slow path: the lock is not held in the case above, so more
586 // than one thread could have reached here trying to add the same category.
587 // Only hold to lock when actually appending a new category, and
588 // check the categories groups again.
589 AutoLock
lock(lock_
);
590 size_t category_index
= base::subtle::Acquire_Load(&g_category_index
);
591 for (size_t i
= 0; i
< category_index
; ++i
) {
592 if (strcmp(g_category_groups
[i
], category_group
) == 0) {
593 return &g_category_group_enabled
[i
];
597 // Create a new category group.
598 DCHECK(category_index
< MAX_CATEGORY_GROUPS
)
599 << "must increase MAX_CATEGORY_GROUPS";
600 if (category_index
< MAX_CATEGORY_GROUPS
) {
601 // Don't hold on to the category_group pointer, so that we can create
602 // category groups with strings not known at compile time (this is
603 // required by SetWatchEvent).
604 const char* new_group
= strdup(category_group
);
605 ANNOTATE_LEAKING_OBJECT_PTR(new_group
);
606 g_category_groups
[category_index
] = new_group
;
607 DCHECK(!g_category_group_enabled
[category_index
]);
608 // Note that if both included and excluded patterns in the
609 // TraceConfig are empty, we exclude nothing,
610 // thereby enabling this category group.
611 UpdateCategoryGroupEnabledFlag(category_index
);
612 category_group_enabled
= &g_category_group_enabled
[category_index
];
613 // Update the max index now.
614 base::subtle::Release_Store(&g_category_index
, category_index
+ 1);
616 category_group_enabled
=
617 &g_category_group_enabled
[g_category_categories_exhausted
];
619 return category_group_enabled
;
622 void TraceLog::GetKnownCategoryGroups(
623 std::vector
<std::string
>* category_groups
) {
624 AutoLock
lock(lock_
);
625 category_groups
->push_back(
626 g_category_groups
[g_category_trace_event_overhead
]);
627 size_t category_index
= base::subtle::NoBarrier_Load(&g_category_index
);
628 for (size_t i
= g_num_builtin_categories
; i
< category_index
; i
++)
629 category_groups
->push_back(g_category_groups
[i
]);
632 void TraceLog::SetEnabled(const TraceConfig
& trace_config
, Mode mode
) {
633 std::vector
<EnabledStateObserver
*> observer_list
;
635 AutoLock
lock(lock_
);
637 // Can't enable tracing when Flush() is in progress.
638 DCHECK(!flush_task_runner_
);
640 InternalTraceOptions new_options
=
641 GetInternalOptionsFromTraceConfig(trace_config
);
643 InternalTraceOptions old_options
= trace_options();
646 if (new_options
!= old_options
) {
647 DLOG(ERROR
) << "Attempting to re-enable tracing with a different "
648 << "set of options.";
652 DLOG(ERROR
) << "Attempting to re-enable tracing with a different mode.";
655 trace_config_
.Merge(trace_config
);
656 UpdateCategoryGroupEnabledFlags();
660 if (dispatching_to_observer_list_
) {
662 << "Cannot manipulate TraceLog::Enabled state from an observer.";
668 if (new_options
!= old_options
) {
669 subtle::NoBarrier_Store(&trace_options_
, new_options
);
670 UseNextTraceBuffer();
673 num_traces_recorded_
++;
675 trace_config_
= TraceConfig(trace_config
);
676 UpdateCategoryGroupEnabledFlags();
677 UpdateSyntheticDelaysFromTraceConfig();
679 if (new_options
& kInternalEnableSampling
) {
680 sampling_thread_
.reset(new TraceSamplingThread
);
681 sampling_thread_
->RegisterSampleBucket(
682 &g_trace_state
[0], "bucket0",
683 Bind(&TraceSamplingThread::DefaultSamplingCallback
));
684 sampling_thread_
->RegisterSampleBucket(
685 &g_trace_state
[1], "bucket1",
686 Bind(&TraceSamplingThread::DefaultSamplingCallback
));
687 sampling_thread_
->RegisterSampleBucket(
688 &g_trace_state
[2], "bucket2",
689 Bind(&TraceSamplingThread::DefaultSamplingCallback
));
690 if (!PlatformThread::Create(0, sampling_thread_
.get(),
691 &sampling_thread_handle_
)) {
692 DCHECK(false) << "failed to create thread";
696 dispatching_to_observer_list_
= true;
697 observer_list
= enabled_state_observer_list_
;
699 // Notify observers outside the lock in case they trigger trace events.
700 for (size_t i
= 0; i
< observer_list
.size(); ++i
)
701 observer_list
[i
]->OnTraceLogEnabled();
704 AutoLock
lock(lock_
);
705 dispatching_to_observer_list_
= false;
709 void TraceLog::SetArgumentFilterPredicate(
710 const ArgumentFilterPredicate
& argument_filter_predicate
) {
711 AutoLock
lock(lock_
);
712 DCHECK(!argument_filter_predicate
.is_null());
713 DCHECK(argument_filter_predicate_
.is_null());
714 argument_filter_predicate_
= argument_filter_predicate
;
717 TraceLog::InternalTraceOptions
TraceLog::GetInternalOptionsFromTraceConfig(
718 const TraceConfig
& config
) {
719 InternalTraceOptions ret
=
720 config
.IsSamplingEnabled() ? kInternalEnableSampling
: kInternalNone
;
721 if (config
.IsArgumentFilterEnabled())
722 ret
|= kInternalEnableArgumentFilter
;
723 switch (config
.GetTraceRecordMode()) {
724 case RECORD_UNTIL_FULL
:
725 return ret
| kInternalRecordUntilFull
;
726 case RECORD_CONTINUOUSLY
:
727 return ret
| kInternalRecordContinuously
;
728 case ECHO_TO_CONSOLE
:
729 return ret
| kInternalEchoToConsole
;
730 case RECORD_AS_MUCH_AS_POSSIBLE
:
731 return ret
| kInternalRecordAsMuchAsPossible
;
734 return kInternalNone
;
737 TraceConfig
TraceLog::GetCurrentTraceConfig() const {
738 AutoLock
lock(lock_
);
739 return trace_config_
;
742 void TraceLog::SetDisabled() {
743 AutoLock
lock(lock_
);
744 SetDisabledWhileLocked();
747 void TraceLog::SetDisabledWhileLocked() {
748 lock_
.AssertAcquired();
753 if (dispatching_to_observer_list_
) {
755 << "Cannot manipulate TraceLog::Enabled state from an observer.";
761 if (sampling_thread_
.get()) {
762 // Stop the sampling thread.
763 sampling_thread_
->Stop();
765 PlatformThread::Join(sampling_thread_handle_
);
767 sampling_thread_handle_
= PlatformThreadHandle();
768 sampling_thread_
.reset();
771 trace_config_
.Clear();
772 subtle::NoBarrier_Store(&watch_category_
, 0);
773 watch_event_name_
= "";
774 UpdateCategoryGroupEnabledFlags();
775 AddMetadataEventsWhileLocked();
777 dispatching_to_observer_list_
= true;
778 std::vector
<EnabledStateObserver
*> observer_list
=
779 enabled_state_observer_list_
;
782 // Dispatch to observers outside the lock in case the observer triggers a
784 AutoUnlock
unlock(lock_
);
785 for (size_t i
= 0; i
< observer_list
.size(); ++i
)
786 observer_list
[i
]->OnTraceLogDisabled();
788 dispatching_to_observer_list_
= false;
791 int TraceLog::GetNumTracesRecorded() {
792 AutoLock
lock(lock_
);
795 return num_traces_recorded_
;
798 void TraceLog::AddEnabledStateObserver(EnabledStateObserver
* listener
) {
799 enabled_state_observer_list_
.push_back(listener
);
802 void TraceLog::RemoveEnabledStateObserver(EnabledStateObserver
* listener
) {
803 std::vector
<EnabledStateObserver
*>::iterator it
=
804 std::find(enabled_state_observer_list_
.begin(),
805 enabled_state_observer_list_
.end(), listener
);
806 if (it
!= enabled_state_observer_list_
.end())
807 enabled_state_observer_list_
.erase(it
);
810 bool TraceLog::HasEnabledStateObserver(EnabledStateObserver
* listener
) const {
811 std::vector
<EnabledStateObserver
*>::const_iterator it
=
812 std::find(enabled_state_observer_list_
.begin(),
813 enabled_state_observer_list_
.end(), listener
);
814 return it
!= enabled_state_observer_list_
.end();
817 TraceLogStatus
TraceLog::GetStatus() const {
818 AutoLock
lock(lock_
);
819 TraceLogStatus result
;
820 result
.event_capacity
= logged_events_
->Capacity();
821 result
.event_count
= logged_events_
->Size();
825 bool TraceLog::BufferIsFull() const {
826 AutoLock
lock(lock_
);
827 return logged_events_
->IsFull();
830 TraceEvent
* TraceLog::AddEventToThreadSharedChunkWhileLocked(
831 TraceEventHandle
* handle
,
832 bool check_buffer_is_full
) {
833 lock_
.AssertAcquired();
835 if (thread_shared_chunk_
&& thread_shared_chunk_
->IsFull()) {
836 logged_events_
->ReturnChunk(thread_shared_chunk_index_
,
837 thread_shared_chunk_
.Pass());
840 if (!thread_shared_chunk_
) {
841 thread_shared_chunk_
=
842 logged_events_
->GetChunk(&thread_shared_chunk_index_
);
843 if (check_buffer_is_full
)
844 CheckIfBufferIsFullWhileLocked();
846 if (!thread_shared_chunk_
)
850 TraceEvent
* trace_event
= thread_shared_chunk_
->AddTraceEvent(&event_index
);
851 if (trace_event
&& handle
) {
852 MakeHandle(thread_shared_chunk_
->seq(), thread_shared_chunk_index_
,
853 event_index
, handle
);
858 void TraceLog::CheckIfBufferIsFullWhileLocked() {
859 lock_
.AssertAcquired();
860 if (logged_events_
->IsFull()) {
861 if (buffer_limit_reached_timestamp_
.is_null()) {
862 buffer_limit_reached_timestamp_
= OffsetNow();
864 SetDisabledWhileLocked();
868 void TraceLog::SetEventCallbackEnabled(const TraceConfig
& trace_config
,
870 AutoLock
lock(lock_
);
871 subtle::NoBarrier_Store(&event_callback_
,
872 reinterpret_cast<subtle::AtomicWord
>(cb
));
873 event_callback_trace_config_
= trace_config
;
874 UpdateCategoryGroupEnabledFlags();
877 void TraceLog::SetEventCallbackDisabled() {
878 AutoLock
lock(lock_
);
879 subtle::NoBarrier_Store(&event_callback_
, 0);
880 UpdateCategoryGroupEnabledFlags();
883 // Flush() works as the following:
884 // 1. Flush() is called in thread A whose task runner is saved in
885 // flush_task_runner_;
886 // 2. If thread_message_loops_ is not empty, thread A posts task to each message
887 // loop to flush the thread local buffers; otherwise finish the flush;
888 // 3. FlushCurrentThread() deletes the thread local event buffer:
889 // - The last batch of events of the thread are flushed into the main buffer;
890 // - The message loop will be removed from thread_message_loops_;
891 // If this is the last message loop, finish the flush;
892 // 4. If any thread hasn't finish its flush in time, finish the flush.
893 void TraceLog::Flush(const TraceLog::OutputCallback
& cb
,
894 bool use_worker_thread
) {
895 FlushInternal(cb
, use_worker_thread
, false);
898 void TraceLog::CancelTracing(const OutputCallback
& cb
) {
900 FlushInternal(cb
, false, true);
903 void TraceLog::FlushInternal(const TraceLog::OutputCallback
& cb
,
904 bool use_worker_thread
,
905 bool discard_events
) {
906 use_worker_thread_
= use_worker_thread
;
908 // Can't flush when tracing is enabled because otherwise PostTask would
909 // - generate more trace events;
910 // - deschedule the calling thread on some platforms causing inaccurate
911 // timing of the trace events.
912 scoped_refptr
<RefCountedString
> empty_result
= new RefCountedString
;
914 cb
.Run(empty_result
, false);
915 LOG(WARNING
) << "Ignored TraceLog::Flush called when tracing is enabled";
919 int generation
= this->generation();
920 // Copy of thread_message_loops_ to be used without locking.
921 std::vector
<scoped_refptr
<SingleThreadTaskRunner
>>
922 thread_message_loop_task_runners
;
924 AutoLock
lock(lock_
);
925 DCHECK(!flush_task_runner_
);
926 flush_task_runner_
= ThreadTaskRunnerHandle::IsSet()
927 ? ThreadTaskRunnerHandle::Get()
929 DCHECK_IMPLIES(thread_message_loops_
.size(), flush_task_runner_
);
930 flush_output_callback_
= cb
;
932 if (thread_shared_chunk_
) {
933 logged_events_
->ReturnChunk(thread_shared_chunk_index_
,
934 thread_shared_chunk_
.Pass());
937 if (thread_message_loops_
.size()) {
938 for (hash_set
<MessageLoop
*>::const_iterator it
=
939 thread_message_loops_
.begin();
940 it
!= thread_message_loops_
.end(); ++it
) {
941 thread_message_loop_task_runners
.push_back((*it
)->task_runner());
946 if (thread_message_loop_task_runners
.size()) {
947 for (size_t i
= 0; i
< thread_message_loop_task_runners
.size(); ++i
) {
948 thread_message_loop_task_runners
[i
]->PostTask(
949 FROM_HERE
, Bind(&TraceLog::FlushCurrentThread
, Unretained(this),
950 generation
, discard_events
));
952 flush_task_runner_
->PostDelayedTask(
953 FROM_HERE
, Bind(&TraceLog::OnFlushTimeout
, Unretained(this), generation
,
955 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs
));
959 FinishFlush(generation
, discard_events
);
962 // Usually it runs on a different thread.
963 void TraceLog::ConvertTraceEventsToTraceFormat(
964 scoped_ptr
<TraceBuffer
> logged_events
,
965 const OutputCallback
& flush_output_callback
,
966 const ArgumentFilterPredicate
& argument_filter_predicate
) {
967 if (flush_output_callback
.is_null())
970 // The callback need to be called at least once even if there is no events
971 // to let the caller know the completion of flush.
972 scoped_refptr
<RefCountedString
> json_events_str_ptr
= new RefCountedString();
973 while (const TraceBufferChunk
* chunk
= logged_events
->NextChunk()) {
974 for (size_t j
= 0; j
< chunk
->size(); ++j
) {
975 size_t size
= json_events_str_ptr
->size();
976 if (size
> kTraceEventBufferSizeInBytes
) {
977 flush_output_callback
.Run(json_events_str_ptr
, true);
978 json_events_str_ptr
= new RefCountedString();
980 json_events_str_ptr
->data().append(",\n");
982 chunk
->GetEventAt(j
)->AppendAsJSON(&(json_events_str_ptr
->data()),
983 argument_filter_predicate
);
986 flush_output_callback
.Run(json_events_str_ptr
, false);
989 void TraceLog::FinishFlush(int generation
, bool discard_events
) {
990 scoped_ptr
<TraceBuffer
> previous_logged_events
;
991 OutputCallback flush_output_callback
;
992 ArgumentFilterPredicate argument_filter_predicate
;
994 if (!CheckGeneration(generation
))
998 AutoLock
lock(lock_
);
1000 previous_logged_events
.swap(logged_events_
);
1001 UseNextTraceBuffer();
1002 thread_message_loops_
.clear();
1004 flush_task_runner_
= NULL
;
1005 flush_output_callback
= flush_output_callback_
;
1006 flush_output_callback_
.Reset();
1008 if (trace_options() & kInternalEnableArgumentFilter
) {
1009 CHECK(!argument_filter_predicate_
.is_null());
1010 argument_filter_predicate
= argument_filter_predicate_
;
1014 if (discard_events
) {
1015 if (!flush_output_callback
.is_null()) {
1016 scoped_refptr
<RefCountedString
> empty_result
= new RefCountedString
;
1017 flush_output_callback
.Run(empty_result
, false);
1022 if (use_worker_thread_
&&
1023 WorkerPool::PostTask(
1024 FROM_HERE
, Bind(&TraceLog::ConvertTraceEventsToTraceFormat
,
1025 Passed(&previous_logged_events
),
1026 flush_output_callback
, argument_filter_predicate
),
1031 ConvertTraceEventsToTraceFormat(previous_logged_events
.Pass(),
1032 flush_output_callback
,
1033 argument_filter_predicate
);
1036 // Run in each thread holding a local event buffer.
1037 void TraceLog::FlushCurrentThread(int generation
, bool discard_events
) {
1039 AutoLock
lock(lock_
);
1040 if (!CheckGeneration(generation
) || !flush_task_runner_
) {
1041 // This is late. The corresponding flush has finished.
1046 // This will flush the thread local buffer.
1047 delete thread_local_event_buffer_
.Get();
1049 AutoLock
lock(lock_
);
1050 if (!CheckGeneration(generation
) || !flush_task_runner_
||
1051 thread_message_loops_
.size())
1054 flush_task_runner_
->PostTask(
1055 FROM_HERE
, Bind(&TraceLog::FinishFlush
, Unretained(this), generation
,
1059 void TraceLog::OnFlushTimeout(int generation
, bool discard_events
) {
1061 AutoLock
lock(lock_
);
1062 if (!CheckGeneration(generation
) || !flush_task_runner_
) {
1063 // Flush has finished before timeout.
1068 << "The following threads haven't finished flush in time. "
1069 "If this happens stably for some thread, please call "
1070 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
1071 "the thread to avoid its trace events from being lost.";
1072 for (hash_set
<MessageLoop
*>::const_iterator it
=
1073 thread_message_loops_
.begin();
1074 it
!= thread_message_loops_
.end(); ++it
) {
1075 LOG(WARNING
) << "Thread: " << (*it
)->thread_name();
1078 FinishFlush(generation
, discard_events
);
1081 void TraceLog::FlushButLeaveBufferIntact(
1082 const TraceLog::OutputCallback
& flush_output_callback
) {
1083 scoped_ptr
<TraceBuffer
> previous_logged_events
;
1084 ArgumentFilterPredicate argument_filter_predicate
;
1086 AutoLock
lock(lock_
);
1087 AddMetadataEventsWhileLocked();
1088 if (thread_shared_chunk_
) {
1089 // Return the chunk to the main buffer to flush the sampling data.
1090 logged_events_
->ReturnChunk(thread_shared_chunk_index_
,
1091 thread_shared_chunk_
.Pass());
1093 previous_logged_events
= logged_events_
->CloneForIteration().Pass();
1095 if (trace_options() & kInternalEnableArgumentFilter
) {
1096 CHECK(!argument_filter_predicate_
.is_null());
1097 argument_filter_predicate
= argument_filter_predicate_
;
1101 ConvertTraceEventsToTraceFormat(previous_logged_events
.Pass(),
1102 flush_output_callback
,
1103 argument_filter_predicate
);
1106 void TraceLog::UseNextTraceBuffer() {
1107 logged_events_
.reset(CreateTraceBuffer());
1108 subtle::NoBarrier_AtomicIncrement(&generation_
, 1);
1109 thread_shared_chunk_
.reset();
1110 thread_shared_chunk_index_
= 0;
1113 TraceEventHandle
TraceLog::AddTraceEvent(
1115 const unsigned char* category_group_enabled
,
1117 unsigned long long id
,
1119 const char** arg_names
,
1120 const unsigned char* arg_types
,
1121 const unsigned long long* arg_values
,
1122 const scoped_refptr
<ConvertableToTraceFormat
>* convertable_values
,
1123 unsigned int flags
) {
1124 int thread_id
= static_cast<int>(base::PlatformThread::CurrentId());
1125 base::TraceTicks now
= base::TraceTicks::Now();
1126 return AddTraceEventWithThreadIdAndTimestamp(
1128 category_group_enabled
,
1131 trace_event_internal::kNoId
, // context_id
1132 trace_event_internal::kNoId
, // bind_id
1143 TraceEventHandle
TraceLog::AddTraceEventWithContextId(
1145 const unsigned char* category_group_enabled
,
1147 unsigned long long id
,
1148 unsigned long long context_id
,
1150 const char** arg_names
,
1151 const unsigned char* arg_types
,
1152 const unsigned long long* arg_values
,
1153 const scoped_refptr
<ConvertableToTraceFormat
>* convertable_values
,
1154 unsigned int flags
) {
1155 int thread_id
= static_cast<int>(base::PlatformThread::CurrentId());
1156 base::TraceTicks now
= base::TraceTicks::Now();
1157 return AddTraceEventWithThreadIdAndTimestamp(
1159 category_group_enabled
,
1163 trace_event_internal::kNoId
, // bind_id
1171 flags
| TRACE_EVENT_FLAG_HAS_CONTEXT_ID
);
1174 // Handle legacy calls to AddTraceEventWithThreadIdAndTimestamp
1175 // with kNoId as bind_id
1176 TraceEventHandle
TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1178 const unsigned char* category_group_enabled
,
1180 unsigned long long id
,
1181 unsigned long long context_id
,
1183 const TraceTicks
& timestamp
,
1185 const char** arg_names
,
1186 const unsigned char* arg_types
,
1187 const unsigned long long* arg_values
,
1188 const scoped_refptr
<ConvertableToTraceFormat
>* convertable_values
,
1189 unsigned int flags
) {
1190 return AddTraceEventWithThreadIdAndTimestamp(
1192 category_group_enabled
,
1196 trace_event_internal::kNoId
, // bind_id
1207 TraceEventHandle
TraceLog::AddTraceEventWithThreadIdAndTimestamp(
1209 const unsigned char* category_group_enabled
,
1211 unsigned long long id
,
1212 unsigned long long context_id
,
1213 unsigned long long bind_id
,
1215 const TraceTicks
& timestamp
,
1217 const char** arg_names
,
1218 const unsigned char* arg_types
,
1219 const unsigned long long* arg_values
,
1220 const scoped_refptr
<ConvertableToTraceFormat
>* convertable_values
,
1221 unsigned int flags
) {
1222 TraceEventHandle handle
= {0, 0, 0};
1223 if (!*category_group_enabled
)
1226 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1227 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1228 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1229 if (thread_is_in_trace_event_
.Get())
1232 AutoThreadLocalBoolean
thread_is_in_trace_event(&thread_is_in_trace_event_
);
1235 DCHECK(!timestamp
.is_null());
1237 if (flags
& TRACE_EVENT_FLAG_MANGLE_ID
) {
1238 if ((flags
& TRACE_EVENT_FLAG_FLOW_IN
) ||
1239 (flags
& TRACE_EVENT_FLAG_FLOW_OUT
))
1240 bind_id
= MangleEventId(bind_id
);
1241 id
= MangleEventId(id
);
1244 TraceTicks offset_event_timestamp
= OffsetTimestamp(timestamp
);
1245 TraceTicks now
= flags
& TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP
1247 : offset_event_timestamp
;
1248 ThreadTicks thread_now
= ThreadNow();
1250 // |thread_local_event_buffer_| can be null if the current thread doesn't have
1251 // a message loop or the message loop is blocked.
1252 InitializeThreadLocalEventBufferIfSupported();
1253 auto thread_local_event_buffer
= thread_local_event_buffer_
.Get();
1255 // Check and update the current thread name only if the event is for the
1256 // current thread to avoid locks in most cases.
1257 if (thread_id
== static_cast<int>(PlatformThread::CurrentId())) {
1258 const char* new_name
=
1259 ThreadIdNameManager::GetInstance()->GetName(thread_id
);
1260 // Check if the thread name has been set or changed since the previous
1261 // call (if any), but don't bother if the new name is empty. Note this will
1262 // not detect a thread name change within the same char* buffer address: we
1263 // favor common case performance over corner case correctness.
1264 if (new_name
!= g_current_thread_name
.Get().Get() && new_name
&&
1266 g_current_thread_name
.Get().Set(new_name
);
1268 AutoLock
thread_info_lock(thread_info_lock_
);
1270 hash_map
<int, std::string
>::iterator existing_name
=
1271 thread_names_
.find(thread_id
);
1272 if (existing_name
== thread_names_
.end()) {
1273 // This is a new thread id, and a new name.
1274 thread_names_
[thread_id
] = new_name
;
1276 // This is a thread id that we've seen before, but potentially with a
1278 std::vector
<StringPiece
> existing_names
= base::SplitStringPiece(
1279 existing_name
->second
, ",", base::KEEP_WHITESPACE
,
1280 base::SPLIT_WANT_NONEMPTY
);
1281 bool found
= std::find(existing_names
.begin(), existing_names
.end(),
1282 new_name
) != existing_names
.end();
1284 if (existing_names
.size())
1285 existing_name
->second
.push_back(',');
1286 existing_name
->second
.append(new_name
);
1293 // This is done sooner rather than later, to avoid creating the event and
1294 // acquiring the lock, which is not needed for ETW as it's already threadsafe.
1295 if (*category_group_enabled
& ENABLED_FOR_ETW_EXPORT
)
1296 TraceEventETWExport::AddEvent(phase
, category_group_enabled
, name
, id
,
1297 num_args
, arg_names
, arg_types
, arg_values
,
1298 convertable_values
);
1301 std::string console_message
;
1302 if (*category_group_enabled
&
1303 (ENABLED_FOR_RECORDING
| ENABLED_FOR_MONITORING
)) {
1304 OptionalAutoLock
lock(&lock_
);
1306 TraceEvent
* trace_event
= NULL
;
1307 if (thread_local_event_buffer
) {
1308 trace_event
= thread_local_event_buffer
->AddTraceEvent(&handle
);
1310 lock
.EnsureAcquired();
1311 trace_event
= AddEventToThreadSharedChunkWhileLocked(&handle
, true);
1315 trace_event
->Initialize(thread_id
,
1316 offset_event_timestamp
,
1319 category_group_enabled
,
1331 #if defined(OS_ANDROID)
1332 trace_event
->SendToATrace();
1336 if (trace_options() & kInternalEchoToConsole
) {
1337 console_message
= EventToConsoleMessage(
1338 phase
== TRACE_EVENT_PHASE_COMPLETE
? TRACE_EVENT_PHASE_BEGIN
: phase
,
1339 timestamp
, trace_event
);
1343 if (console_message
.size())
1344 LOG(ERROR
) << console_message
;
1346 if (reinterpret_cast<const unsigned char*>(
1347 subtle::NoBarrier_Load(&watch_category_
)) == category_group_enabled
) {
1348 bool event_name_matches
;
1349 WatchEventCallback watch_event_callback_copy
;
1351 AutoLock
lock(lock_
);
1352 event_name_matches
= watch_event_name_
== name
;
1353 watch_event_callback_copy
= watch_event_callback_
;
1355 if (event_name_matches
) {
1356 if (!watch_event_callback_copy
.is_null())
1357 watch_event_callback_copy
.Run();
1361 if (*category_group_enabled
& ENABLED_FOR_EVENT_CALLBACK
) {
1362 EventCallback event_callback
= reinterpret_cast<EventCallback
>(
1363 subtle::NoBarrier_Load(&event_callback_
));
1364 if (event_callback
) {
1366 offset_event_timestamp
,
1367 phase
== TRACE_EVENT_PHASE_COMPLETE
? TRACE_EVENT_PHASE_BEGIN
: phase
,
1368 category_group_enabled
, name
, id
, num_args
, arg_names
, arg_types
,
1373 if (thread_local_event_buffer
)
1374 thread_local_event_buffer
->ReportOverhead(now
, thread_now
);
1379 // May be called when a COMPELETE event ends and the unfinished event has been
1380 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
1381 std::string
TraceLog::EventToConsoleMessage(unsigned char phase
,
1382 const TraceTicks
& timestamp
,
1383 TraceEvent
* trace_event
) {
1384 AutoLock
thread_info_lock(thread_info_lock_
);
1386 // The caller should translate TRACE_EVENT_PHASE_COMPLETE to
1387 // TRACE_EVENT_PHASE_BEGIN or TRACE_EVENT_END.
1388 DCHECK(phase
!= TRACE_EVENT_PHASE_COMPLETE
);
1392 trace_event
? trace_event
->thread_id() : PlatformThread::CurrentId();
1393 if (phase
== TRACE_EVENT_PHASE_END
) {
1394 duration
= timestamp
- thread_event_start_times_
[thread_id
].top();
1395 thread_event_start_times_
[thread_id
].pop();
1398 std::string thread_name
= thread_names_
[thread_id
];
1399 if (thread_colors_
.find(thread_name
) == thread_colors_
.end())
1400 thread_colors_
[thread_name
] = (thread_colors_
.size() % 6) + 1;
1402 std::ostringstream log
;
1403 log
<< base::StringPrintf("%s: \x1b[0;3%dm", thread_name
.c_str(),
1404 thread_colors_
[thread_name
]);
1407 if (thread_event_start_times_
.find(thread_id
) !=
1408 thread_event_start_times_
.end())
1409 depth
= thread_event_start_times_
[thread_id
].size();
1411 for (size_t i
= 0; i
< depth
; ++i
)
1415 trace_event
->AppendPrettyPrinted(&log
);
1416 if (phase
== TRACE_EVENT_PHASE_END
)
1417 log
<< base::StringPrintf(" (%.3f ms)", duration
.InMillisecondsF());
1421 if (phase
== TRACE_EVENT_PHASE_BEGIN
)
1422 thread_event_start_times_
[thread_id
].push(timestamp
);
1427 void TraceLog::AddTraceEventEtw(char phase
,
1430 const char* extra
) {
1432 TraceEventETWProvider::Trace(name
, phase
, id
, extra
);
1434 INTERNAL_TRACE_EVENT_ADD(phase
, "ETW Trace Event", name
,
1435 TRACE_EVENT_FLAG_COPY
, "id", id
, "extra", extra
);
1438 void TraceLog::AddTraceEventEtw(char phase
,
1441 const std::string
& extra
) {
1443 TraceEventETWProvider::Trace(name
, phase
, id
, extra
);
1445 INTERNAL_TRACE_EVENT_ADD(phase
, "ETW Trace Event", name
,
1446 TRACE_EVENT_FLAG_COPY
, "id", id
, "extra", extra
);
1449 void TraceLog::UpdateTraceEventDuration(
1450 const unsigned char* category_group_enabled
,
1452 TraceEventHandle handle
) {
1453 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
1454 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
1455 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
1456 if (thread_is_in_trace_event_
.Get())
1459 AutoThreadLocalBoolean
thread_is_in_trace_event(&thread_is_in_trace_event_
);
1461 ThreadTicks thread_now
= ThreadNow();
1462 TraceTicks now
= OffsetNow();
1464 std::string console_message
;
1465 if (*category_group_enabled
& ENABLED_FOR_RECORDING
) {
1466 OptionalAutoLock
lock(&lock_
);
1468 TraceEvent
* trace_event
= GetEventByHandleInternal(handle
, &lock
);
1470 DCHECK(trace_event
->phase() == TRACE_EVENT_PHASE_COMPLETE
);
1471 trace_event
->UpdateDuration(now
, thread_now
);
1472 #if defined(OS_ANDROID)
1473 trace_event
->SendToATrace();
1477 if (trace_options() & kInternalEchoToConsole
) {
1479 EventToConsoleMessage(TRACE_EVENT_PHASE_END
, now
, trace_event
);
1483 if (console_message
.size())
1484 LOG(ERROR
) << console_message
;
1486 if (*category_group_enabled
& ENABLED_FOR_EVENT_CALLBACK
) {
1487 EventCallback event_callback
= reinterpret_cast<EventCallback
>(
1488 subtle::NoBarrier_Load(&event_callback_
));
1489 if (event_callback
) {
1490 event_callback(now
, TRACE_EVENT_PHASE_END
, category_group_enabled
, name
,
1491 trace_event_internal::kNoId
, 0,
1492 nullptr, nullptr, nullptr, TRACE_EVENT_FLAG_NONE
);
1497 void TraceLog::SetWatchEvent(const std::string
& category_name
,
1498 const std::string
& event_name
,
1499 const WatchEventCallback
& callback
) {
1500 const unsigned char* category
=
1501 GetCategoryGroupEnabled(category_name
.c_str());
1502 AutoLock
lock(lock_
);
1503 subtle::NoBarrier_Store(&watch_category_
,
1504 reinterpret_cast<subtle::AtomicWord
>(category
));
1505 watch_event_name_
= event_name
;
1506 watch_event_callback_
= callback
;
1509 void TraceLog::CancelWatchEvent() {
1510 AutoLock
lock(lock_
);
1511 subtle::NoBarrier_Store(&watch_category_
, 0);
1512 watch_event_name_
= "";
1513 watch_event_callback_
.Reset();
1516 uint64
TraceLog::MangleEventId(uint64 id
) {
1517 return id
^ process_id_hash_
;
1520 void TraceLog::AddMetadataEventsWhileLocked() {
1521 lock_
.AssertAcquired();
1523 #if !defined(OS_NACL) // NaCl shouldn't expose the process id.
1524 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1525 0, "num_cpus", "number",
1526 base::SysInfo::NumberOfProcessors());
1529 int current_thread_id
= static_cast<int>(base::PlatformThread::CurrentId());
1530 if (process_sort_index_
!= 0) {
1531 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1532 current_thread_id
, "process_sort_index",
1533 "sort_index", process_sort_index_
);
1536 if (process_name_
.size()) {
1537 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1538 current_thread_id
, "process_name", "name",
1542 if (process_labels_
.size() > 0) {
1543 std::vector
<std::string
> labels
;
1544 for (base::hash_map
<int, std::string
>::iterator it
=
1545 process_labels_
.begin();
1546 it
!= process_labels_
.end(); it
++) {
1547 labels
.push_back(it
->second
);
1549 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1550 current_thread_id
, "process_labels", "labels",
1551 base::JoinString(labels
, ","));
1554 // Thread sort indices.
1555 for (hash_map
<int, int>::iterator it
= thread_sort_indices_
.begin();
1556 it
!= thread_sort_indices_
.end(); it
++) {
1557 if (it
->second
== 0)
1559 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1560 it
->first
, "thread_sort_index", "sort_index",
1565 AutoLock
thread_info_lock(thread_info_lock_
);
1566 for (hash_map
<int, std::string
>::iterator it
= thread_names_
.begin();
1567 it
!= thread_names_
.end(); it
++) {
1568 if (it
->second
.empty())
1570 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1571 it
->first
, "thread_name", "name", it
->second
);
1574 // If buffer is full, add a metadata record to report this.
1575 if (!buffer_limit_reached_timestamp_
.is_null()) {
1576 InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL
, false),
1577 current_thread_id
, "trace_buffer_overflowed",
1579 buffer_limit_reached_timestamp_
);
1583 void TraceLog::WaitSamplingEventForTesting() {
1584 if (!sampling_thread_
)
1586 sampling_thread_
->WaitSamplingEventForTesting();
1589 void TraceLog::DeleteForTesting() {
1590 DeleteTraceLogForTesting::Delete();
1593 TraceEvent
* TraceLog::GetEventByHandle(TraceEventHandle handle
) {
1594 return GetEventByHandleInternal(handle
, NULL
);
1597 TraceEvent
* TraceLog::GetEventByHandleInternal(TraceEventHandle handle
,
1598 OptionalAutoLock
* lock
) {
1599 if (!handle
.chunk_seq
)
1602 if (thread_local_event_buffer_
.Get()) {
1603 TraceEvent
* trace_event
=
1604 thread_local_event_buffer_
.Get()->GetEventByHandle(handle
);
1609 // The event has been out-of-control of the thread local buffer.
1610 // Try to get the event from the main buffer with a lock.
1612 lock
->EnsureAcquired();
1614 if (thread_shared_chunk_
&&
1615 handle
.chunk_index
== thread_shared_chunk_index_
) {
1616 return handle
.chunk_seq
== thread_shared_chunk_
->seq()
1617 ? thread_shared_chunk_
->GetEventAt(handle
.event_index
)
1621 return logged_events_
->GetEventByHandle(handle
);
1624 void TraceLog::SetProcessID(int process_id
) {
1625 process_id_
= process_id
;
1626 // Create a FNV hash from the process ID for XORing.
1627 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
1628 unsigned long long offset_basis
= 14695981039346656037ull;
1629 unsigned long long fnv_prime
= 1099511628211ull;
1630 unsigned long long pid
= static_cast<unsigned long long>(process_id_
);
1631 process_id_hash_
= (offset_basis
^ pid
) * fnv_prime
;
1634 void TraceLog::SetProcessSortIndex(int sort_index
) {
1635 AutoLock
lock(lock_
);
1636 process_sort_index_
= sort_index
;
1639 void TraceLog::SetProcessName(const std::string
& process_name
) {
1640 AutoLock
lock(lock_
);
1641 process_name_
= process_name
;
1644 void TraceLog::UpdateProcessLabel(int label_id
,
1645 const std::string
& current_label
) {
1646 if (!current_label
.length())
1647 return RemoveProcessLabel(label_id
);
1649 AutoLock
lock(lock_
);
1650 process_labels_
[label_id
] = current_label
;
1653 void TraceLog::RemoveProcessLabel(int label_id
) {
1654 AutoLock
lock(lock_
);
1655 base::hash_map
<int, std::string
>::iterator it
=
1656 process_labels_
.find(label_id
);
1657 if (it
== process_labels_
.end())
1660 process_labels_
.erase(it
);
1663 void TraceLog::SetThreadSortIndex(PlatformThreadId thread_id
, int sort_index
) {
1664 AutoLock
lock(lock_
);
1665 thread_sort_indices_
[static_cast<int>(thread_id
)] = sort_index
;
1668 void TraceLog::SetTimeOffset(TimeDelta offset
) {
1669 time_offset_
= offset
;
1672 size_t TraceLog::GetObserverCountForTest() const {
1673 return enabled_state_observer_list_
.size();
1676 void TraceLog::SetCurrentThreadBlocksMessageLoop() {
1677 thread_blocks_message_loop_
.Set(true);
1678 if (thread_local_event_buffer_
.Get()) {
1679 // This will flush the thread local buffer.
1680 delete thread_local_event_buffer_
.Get();
1684 TraceBuffer
* TraceLog::CreateTraceBuffer() {
1685 InternalTraceOptions options
= trace_options();
1686 if (options
& kInternalRecordContinuously
)
1687 return TraceBuffer::CreateTraceBufferRingBuffer(
1688 kTraceEventRingBufferChunks
);
1689 else if ((options
& kInternalEnableSampling
) && mode_
== MONITORING_MODE
)
1690 return TraceBuffer::CreateTraceBufferRingBuffer(
1691 kMonitorTraceEventBufferChunks
);
1692 else if (options
& kInternalEchoToConsole
)
1693 return TraceBuffer::CreateTraceBufferRingBuffer(
1694 kEchoToConsoleTraceEventBufferChunks
);
1695 else if (options
& kInternalRecordAsMuchAsPossible
)
1696 return TraceBuffer::CreateTraceBufferVectorOfSize(
1697 kTraceEventVectorBigBufferChunks
);
1698 return TraceBuffer::CreateTraceBufferVectorOfSize(
1699 kTraceEventVectorBufferChunks
);
1702 void ConvertableToTraceFormat::EstimateTraceMemoryOverhead(
1703 TraceEventMemoryOverhead
* overhead
) {
1704 overhead
->Add("ConvertableToTraceFormat(Unknown)", sizeof(*this));
1707 } // namespace trace_event
1710 namespace trace_event_internal
{
1712 ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
1713 const char* category_group
,
1715 // The single atom works because for now the category_group can only be "gpu".
1716 DCHECK_EQ(strcmp(category_group
, "gpu"), 0);
1717 static TRACE_EVENT_API_ATOMIC_WORD atomic
= 0;
1718 INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
1719 category_group
, atomic
, category_group_enabled_
);
1721 if (*category_group_enabled_
) {
1723 TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
1724 TRACE_EVENT_PHASE_COMPLETE
,
1725 category_group_enabled_
,
1727 trace_event_internal::kNoId
, // id
1728 trace_event_internal::kNoId
, // context_id
1729 static_cast<int>(base::PlatformThread::CurrentId()), // thread_id
1730 base::TraceTicks::Now(),
1731 trace_event_internal::kZeroNumArgs
,
1736 TRACE_EVENT_FLAG_NONE
);
1740 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
1741 if (*category_group_enabled_
) {
1742 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_
, name_
,
1747 } // namespace trace_event_internal