Thread-local trace-event buffers

Thread-local trace-event buffers

Previously we use a central trace-event buffer to store trace events
from all threads, which needs a lock. Measurement showed that on
Android the lock contributes over 50% of the total overhead of
trace event.

Use thread-local trace-event buffers so that in most times trace
events can be handled lock-free.

TraceLog::Flush() now may asynchronously call the callback.

TODO: Now for a message loop running a blocking task, async flush
doesn't work. The async flush will timeout and finish without
collecting the last batch of such thread if any.

On Nexus 4 this patch can reduce the average overhead of trace_event
from 15~20us to about 5~8us for a busy app. Note the numbers are not
very accurate because
- the time tick seems 30us on Android. The average number may be just
a result of increased percentage of trace events whose overhead < 30us.
- there are differences in the measurement method of the overhead
because of the change of the code structure.

BUG=264667
TEST=Updated existing tests: TraceEventTestFixture.DataCapturedOnThread
and TraceEventTestFixture.DataCapturedManyThreads. Existing unit/browser
tests using trace_event should still pass.
R=nduca, dsinclair
TBR=phajdan.jr (for base/test/trace_event_analyzer_unittest.cc)

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=221766

[Xianzhu, 2013-08-13 19:42:01]

Uploaded the patch set for pre-review. Adding unit tests.

[dsinclair, 2013-08-13 21:04:41]

Added a few comments.

My concern with this is that, at least for me, this makes it a lot harder to
reason about what's happening. What are the semantics around when we have to
lock_ and when it's safe to go unlocked?

There is one potential issue that I see with this. If we're tracing with a fixed
size buffer (i.e. continuous events off) it's possible for a thread to not
contribute any of its events.

For example, we start tracing and threadA traces 100 events. threadB then traces
the other 500k events. Because the buffer is now full, we'll end up dropping the
100 events from threadA even though they came before the threadB events and
should be included.

This makes it look like threadA didn't do anything. When it was just that it
didn't get an opportunity to output the 100 events.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
File base/debug/trace_event_android.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
base/debug/trace_event_android.cc:101: const char* category_group =
GetCategoryGroupName(category_group_enabled);
This seems unrelated, move to its own CL?

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:765: };
DISABLE_COPY_AND_ASSIGN?

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:1423: void
TraceLog::EchoEventToConsoleIfEnabled(const TraceEvent& event) {
Could this, mostly, be moved to it's own CL? Then, this CL would just have the
code where the EchoToConsoleContext was added.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_impl.h
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.h:593: subtle::AtomicWord echo_to_console_context_;
nit: the other AtomicWords have a comment with the type, can this one be added
as well?

[Xianzhu, 2013-08-13 23:35:50]

Thanks for review. Uploaded Patch Set 2. Still for preview until we address all
potential issues.

On 2013/08/13 21:04:41, dsinclair wrote:
> Added a few comments.
> 
> My concern with this is that, at least for me, this makes it a lot harder to
> reason about what's happening. What are the semantics around when we have to
> lock_ and when it's safe to go unlocked?

I think this is the fundamental issue what needs to be resolved before this CL
could be submitted. I listed some of my thoughts in the doc
https://docs.google.com/a/chromium.org/document/d/1KbwKHEHxbkcnfjVChQ_3Mg4Gth...
while may address part of your question. Feel free to add comments or even edit
it.

> There is one potential issue that I see with this. If we're tracing with a
fixed
> size buffer (i.e. continuous events off) it's possible for a thread to not
> contribute any of its events.
> 
> For example, we start tracing and threadA traces 100 events. threadB then
traces
> the other 500k events. Because the buffer is now full, we'll end up dropping
the
> 100 events from threadA even though they came before the threadB events and
> should be included.
> 
> This makes it look like threadA didn't do anything. When it was just that it
> didn't get an opportunity to output the 100 events.

Changed AddEventToMainBufferWhileLocked to allow thread-local events to be
flushed even if the buffer is full. The buffer won't be overflowed too much
because no more new thread-local events will be buffered since the buffer is
full. 

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
File base/debug/trace_event_android.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
base/debug/trace_event_android.cc:101: const char* category_group =
GetCategoryGroupName(category_group_enabled);
On 2013/08/13 21:04:42, dsinclair wrote:
> This seems unrelated, move to its own CL?

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:765: };
On 2013/08/13 21:04:42, dsinclair wrote:
> DISABLE_COPY_AND_ASSIGN?

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:1423: void
TraceLog::EchoEventToConsoleIfEnabled(const TraceEvent& event) {
On 2013/08/13 21:04:42, dsinclair wrote:
> Could this, mostly, be moved to it's own CL? Then, this CL would just have the
> code where the EchoToConsoleContext was added.

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_impl.h
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.h:593: subtle::AtomicWord echo_to_console_context_;
On 2013/08/13 21:04:42, dsinclair wrote:
> nit: the other AtomicWords have a comment with the type, can this one be added
> as well?

Done.

[dsinclair, 2013-08-14 15:15:59]

Thanks a lot for the doc, clarified some things for me. Added a few comments
below. I think the flush is the biggest source of confusion, mostly due to the
thread hopping and when the lock has to be held.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:763: void CheckThread() {
Name is a bit generic, what about something like:

CheckThisIsCurrentBuffer() ?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:767: TraceLog* trace_log_;
Are we making the assumption that, since TraceLog is a leaky singleton this will
always be valid as long as the thread exists?

If so, can we add a comment to that affect?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:778: DCHECK(message_loop);
What does it mean if this fails? Is it possible in Release mode that this will
happen?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:817: NotificationHelper* notifier) {
lock_.AssertAcquired()?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:881: struct EchoToConsoleContext {
Can we move this up into the other anonymous namespace at the top of the file?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1248: if (next_message_loop !=
thread_message_loops_.end()) {
The flush logic is, I think, the biggest confusion. Let me just check I've got
this right.

threadA kicks off the flush. It stores itself into flush_message_loop.

threadA then gets the first thread message loop and tells it to flush. That
thread, when finished will send a message to threadA to tell it to flush the
next one. This will work through all of the loops, including the message loop
for threadA and flush all the thread data.

threadA will then continue the rest of the flush procedure.

Correct? Would it be possible to get a comment here to explain the flushing?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1339: if (MessageLoop::current()) {
Why is this inside the if (thread_id ...) check? In theory, threadA could
receive the thread_id of threadB and, as long as threadA has a message loop, we
should be able to add the event to the threadA local events.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1358: hash_map<int, std::string>::iterator
existing_name =
Why is this safe to do without holding the lock? Is it because the only thing
accessed/edited is the current thread_id's data?

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:614: base::hash_set<MessageLoop*>
thread_message_loops_;
Can we add a comment to thread_message_loops_ that this contains the message
loops of threads that have had at least one AddEvent called?

[nduca, 2013-08-14 18:37:11]

I left a few comments on the doc. first off, ___thank you so much for trying to
address this issue!!!__ This has been the biggest wart in tracing since it was
written!

As I noted in the doc, I am worried about the periodic flushing. We know from
experiments from jamesr and our overall experience that postTask pretty commonly
deschedules the calling thread in favor of the activated thread (seen on linux,
but probably happens everywhere). It is a problem to use postTasks in
about:tracing during data collection (fine at the end of recording), because it
risks changing the performance of the system.

I would encourage us to consider simplifying our circular recording modes and
eliminating the global tracelog in favor of entirely per thread solutions, if
possible. While it means we can't enforce a per process limit, it will avoid the
performance risk of a postTask, right?

Maybe best to discuss on the doc? I'm fine either way.

[nduca, 2013-08-14 18:37:51]

Also, I think we might want to seriously pursue the X event. Its an easier
change than this (especially if we buy into TracedValue replacing the existing
args mechanisms), and we know it will reduce locking overhead by 2x.

[Xianzhu, 2013-08-14 20:21:04]

On 2013/08/14 18:37:11, nduca wrote:
> I left a few comments on the doc. first off, ___thank you so much for trying
to
> address this issue!!!__ This has been the biggest wart in tracing since it was
> written!
> 
> As I noted in the doc, I am worried about the periodic flushing. We know from
> experiments from jamesr and our overall experience that postTask pretty
commonly
> deschedules the calling thread in favor of the activated thread (seen on
linux,
> but probably happens everywhere). It is a problem to use postTasks in
> about:tracing during data collection (fine at the end of recording), because
it
> risks changing the performance of the system.
> 
> I would encourage us to consider simplifying our circular recording modes and
> eliminating the global tracelog in favor of entirely per thread solutions, if
> possible. While it means we can't enforce a per process limit, it will avoid
the
> performance risk of a postTask, right?
> 
> Maybe best to discuss on the doc? I'm fine either way.

I prefer the doc.

> Also, I think we might want to seriously pursue the X event. Its an easier
> change than this (especially if we buy into TracedValue replacing the existing
> args mechanisms), and we know it will reduce locking overhead by 2x.

Agreed. I think we can implement X event first and see the results.

[Xianzhu, 2013-08-14 21:28:33]

*** Patch Set 3 is still for preview. The document is open for discussion. ***

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
File base/debug/trace_event_android.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_and...
base/debug/trace_event_android.cc:101: const char* category_group =
GetCategoryGroupName(category_group_enabled);
On 2013/08/13 21:04:42, dsinclair wrote:
> This seems unrelated, move to its own CL?

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:765: };
On 2013/08/13 21:04:42, dsinclair wrote:
> DISABLE_COPY_AND_ASSIGN?

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:1423: void
TraceLog::EchoEventToConsoleIfEnabled(const TraceEvent& event) {
On 2013/08/13 21:04:42, dsinclair wrote:
> Could this, mostly, be moved to it's own CL? Then, this CL would just have the
> code where the EchoToConsoleContext was added.

Done.

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_impl.h
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/1004/base/debug/trace_event_imp...
base/debug/trace_event_impl.h:593: subtle::AtomicWord echo_to_console_context_;
On 2013/08/13 21:04:42, dsinclair wrote:
> nit: the other AtomicWords have a comment with the type, can this one be added
> as well?

Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:763: void CheckThread() {
On 2013/08/14 15:15:59, dsinclair wrote:
> Name is a bit generic, what about something like:
> 
> CheckThisIsCurrentBuffer() ?

Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:767: TraceLog* trace_log_;
On 2013/08/14 15:15:59, dsinclair wrote:
> Are we making the assumption that, since TraceLog is a leaky singleton this
will
> always be valid as long as the thread exists?
> 
> If so, can we add a comment to that affect?

Yes. Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:778: DCHECK(message_loop);
On 2013/08/14 15:15:59, dsinclair wrote:
> What does it mean if this fails? Is it possible in Release mode that this will
> happen?

It never fails because ThreadLocalEventBuffer is created only for threads having
message loops. Removed the DCHECK and added comments.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:817: NotificationHelper* notifier) {
On 2013/08/14 15:15:59, dsinclair wrote:
> lock_.AssertAcquired()?

Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:881: struct EchoToConsoleContext {
On 2013/08/14 15:15:59, dsinclair wrote:
> Can we move this up into the other anonymous namespace at the top of the file?

Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1248: if (next_message_loop !=
thread_message_loops_.end()) {
On 2013/08/14 15:15:59, dsinclair wrote:
> The flush logic is, I think, the biggest confusion. Let me just check I've got
> this right.
> 
> threadA kicks off the flush. It stores itself into flush_message_loop.
> 
> threadA then gets the first thread message loop and tells it to flush. That
> thread, when finished will send a message to threadA to tell it to flush the
> next one. This will work through all of the loops, including the message loop
> for threadA and flush all the thread data.
> 
> threadA will then continue the rest of the flush procedure.
> 
> Correct? Would it be possible to get a comment here to explain the flushing?

Exactly :)
Added comments.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1339: if (MessageLoop::current()) {
On 2013/08/14 15:15:59, dsinclair wrote:
> Why is this inside the if (thread_id ...) check? In theory, threadA could
> receive the thread_id of threadB and, as long as threadA has a message loop,
we
> should be able to add the event to the threadA local events.

Done.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1358: hash_map<int, std::string>::iterator
existing_name =
On 2013/08/14 15:15:59, dsinclair wrote:
> Why is this safe to do without holding the lock? Is it because the only thing
> accessed/edited is the current thread_id's data?

This is a bug. Added lock.

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/11001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:614: base::hash_set<MessageLoop*>
thread_message_loops_;
On 2013/08/14 15:15:59, dsinclair wrote:
> Can we add a comment to thread_message_loops_ that this contains the message
> loops of threads that have had at least one AddEvent called?

Done.

[dsinclair, 2013-08-16 14:38:32]

A few more comments but I think it is a lot better in terms of understanding the
flow of data. Thanks a lot of adding the comments and clarifying my
understanding.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:76: "trace-event-overhead"
This should probably be disabled-by-default-trace-event-overhead category if
we're always going to be saying it's always available.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:822:
trace_event_internal::SetTraceValue(overhead_.InSecondsF() / event_count_,
Why seconds? Do we really expect this to be outside the millisecond range?

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1367: // Run in each of the thread holding a
local event buffer.
s/thread/threads

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1373: flush_message_loop_->PostTask(FROM_HERE,
Having this here makes the flow a lot simpler to follow.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:616: // is added into the local event buffer.
s/is//

[Xianzhu, 2013-08-16 19:41:03]

- Updated the document, added comments about fully-local thread buffers.

- Made THREAD_LOCAL_BUFFERS an option which is off by default. As the current
overhead of locking is small for Desktop Chrome, we can enable the option on
Android first.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:76: "trace-event-overhead"
On 2013/08/16 14:38:32, dsinclair wrote:
> This should probably be disabled-by-default-trace-event-overhead category if
> we're always going to be saying it's always available.

I'd like let it enabled by default to prevent the user from being surprised when
seeing a trace duration much longer than expected. The extra overhead for
reporting overhead is small.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:822:
trace_event_internal::SetTraceValue(overhead_.InSecondsF() / event_count_,
On 2013/08/16 14:38:32, dsinclair wrote:
> Why seconds? Do we really expect this to be outside the millisecond range?

Done.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1367: // Run in each of the thread holding a
local event buffer.
On 2013/08/16 14:38:32, dsinclair wrote:
> s/thread/threads

Done.

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/20001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:616: // is added into the local event buffer.
On 2013/08/16 14:38:32, dsinclair wrote:
> s/is//

Done.

[nduca, 2013-08-17 02:26:19]

I'd suggest enabling this everywhere, or nowhere. Not android specific. Tracing
gets a lot of use on desktops... that'll give us very quick rapid signal if
we've broken stuff or survived.

[Xianzhu, 2013-08-27 18:21:43]

On 2013/08/17 02:26:19, nduca wrote:
> I'd suggest enabling this everywhere, or nowhere. Not android specific.
Tracing
> gets a lot of use on desktops... that'll give us very quick rapid signal if
> we've broken stuff or survived.

PTAL. Changes in the last Patch Set:
- Removed THREAD_LOCAL_BUFFERS opotion;
- Updated unit tests;
- Updated callsites of TraceLog::Flush() for the asynchronous behavior

[Xianzhu, 2013-08-27 18:41:15]

On 2013/08/27 18:21:43, Xianzhu wrote:
> PTAL. Changes in the last Patch Set:
> - Removed THREAD_LOCAL_BUFFERS opotion;
> - Updated unit tests;
> - Updated callsites of TraceLog::Flush() for the asynchronous behavior

Sorry, I need to update more callsites. Please wait a while.

[Xianzhu, 2013-08-28 21:37:52]

The last patch set is now ready for review. Thanks for your patience.

[dsinclair, 2013-08-29 14:24:32]

This is looking really good. The code is a lot easier to follow and the comments
really clarify things. Thanks a lot for the cleanups.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:77: // For reporting trace_event overhead. For
thread local event buffers only.
After this patch, will we have non-thread-local event buffers? If not, let's
just drop this comment.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:101: TimeTicks::ThreadNow() : TimeTicks();
nit: indented too far.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:831: // ThreadLocalEventBuffer is created only if
the thread has message loop, so
nit: if the thread has a message loop

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:851: overhead_.InMillisecondsF() / event_count_,
Does overhead_ get an initial value of 0 by default? What happens if
ReportOverhead is never called for some reason?

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:887: if
(g_category_group_enabled[g_category_trace_event_overhead]) {
if (!g_category_group_enabled[g_category_trace_event_overhead])
  return;

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1310: void
TraceLog::CheckIfBufferIsFullWhileLocked(NotificationHelper* notifier) {
lock_.AssertAcquired();

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1340: if (IsEnabled()) {
Is this, basically, to stop us from doing any post tasks while we're tracing?

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1342: cb.Run(empty_result, false);
Should we check if cb.isNull() here before we try to run it?

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1399:
flush_output_callback_.Run(json_events_str_ptr, has_more_events);
Should we check if flush_output_callback_ exists?

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:55: }
nit:  // namespace BASE_HASH_NAMESPACE

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:403: // directly with (empty_string, false).
Confused about the false. So, if we call when tracing is enabled, why is
'has_more_events' false? Wouldn't it be true since we're still tracing?

https://codereview.chromium.org/22962004/diff/40001/content/browser/tracing/t...
File content/browser/tracing/trace_controller_impl.cc (right):

https://codereview.chromium.org/22962004/diff/40001/content/browser/tracing/t...
content/browser/tracing/trace_controller_impl.cc:320: // received.
nit: missing )

[Xianzhu, 2013-08-29 17:42:12]

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:77: // For reporting trace_event overhead. For
thread local event buffers only.
On 2013/08/29 14:24:32, dsinclair wrote:
> After this patch, will we have non-thread-local event buffers? If not, let's
> just drop this comment.

Yes, trace events from a thread without a message loop (e.g. some short-lived
worker thread) will still use the main buffer directly.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:101: TimeTicks::ThreadNow() : TimeTicks();
On 2013/08/29 14:24:32, dsinclair wrote:
> nit: indented too far.

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:831: // ThreadLocalEventBuffer is created only if
the thread has message loop, so
On 2013/08/29 14:24:32, dsinclair wrote:
> nit: if the thread has a message loop

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:851: overhead_.InMillisecondsF() / event_count_,
On 2013/08/29 14:24:32, dsinclair wrote:
> Does overhead_ get an initial value of 0 by default?
Yes, set by the default ctor of TimeDelta.

> What happens if ReportOverhead is never called for some reason?
If event_count_ is zero, this block won't be executed. The trace-viewer will
discard the async begin event sent in the constructor because there is no
matching async end.

This happens in either of the following cases:
- no event generated for the thread;
- the thread has no message loop;
- trace_event_overhead is disabled;

Added comments above the if (event_count_) condition.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:887: if
(g_category_group_enabled[g_category_trace_event_overhead]) {
On 2013/08/29 14:24:32, dsinclair wrote:
> if (!g_category_group_enabled[g_category_trace_event_overhead])
>   return;

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1310: void
TraceLog::CheckIfBufferIsFullWhileLocked(NotificationHelper* notifier) {
On 2013/08/29 14:24:32, dsinclair wrote:
> lock_.AssertAcquired();

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1340: if (IsEnabled()) {
On 2013/08/29 14:24:32, dsinclair wrote:
> Is this, basically, to stop us from doing any post tasks while we're tracing?

Yes.

In addition, as posting tasks will generate more trace events, it will badly
interfere with the flush process. For example, just after a thread-local buffer
is flushed and destroyed, new trace event from the thread will cause a new
thread-local buffer to be created, then FlushNextThreadOrFinish() will never
finish.

Flushing while enabled happens on chrome-android because the gpu process and the
browser process are the same process. As the gpu process is still registered as
a subprocess, the TraceLog in the process will be enabled twice, and be disabled
and flushed twice on the end of tracing.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1342: cb.Run(empty_result, false);
On 2013/08/29 14:24:32, dsinclair wrote:
> Should we check if cb.isNull() here before we try to run it?

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1399:
flush_output_callback_.Run(json_events_str_ptr, has_more_events);
On 2013/08/29 14:24:32, dsinclair wrote:
> Should we check if flush_output_callback_ exists?

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:55: }
On 2013/08/29 14:24:32, dsinclair wrote:
> nit:  // namespace BASE_HASH_NAMESPACE

Done.

https://codereview.chromium.org/22962004/diff/40001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:403: // directly with (empty_string, false).
On 2013/08/29 14:24:32, dsinclair wrote:
> Confused about the false. So, if we call when tracing is enabled, why is
> 'has_more_events' false? Wouldn't it be true since we're still tracing?

Added comments:
Due to the implementation of thread-local buffers, flush can't be
done when tracing is enabled. If called when tracing is enabled, the
callback will be called directly with (empty_string, false) to indicate
the end of this unsuccessful flush.

(otherwise the caller should wait until a callback with false, but this won't
happen in this flush).

https://codereview.chromium.org/22962004/diff/40001/content/browser/tracing/t...
File content/browser/tracing/trace_controller_impl.cc (right):

https://codereview.chromium.org/22962004/diff/40001/content/browser/tracing/t...
content/browser/tracing/trace_controller_impl.cc:320: // received.
On 2013/08/29 14:24:32, dsinclair wrote:
> nit: missing )

Done.

[dsinclair, 2013-08-29 17:49:02]

lgtm, this is good to me once nduca is happy.

[nduca, 2013-08-30 01:05:34]

lgtm. Xianzhu, you constantly amaze me.

[commit-bot: I haz the power, 2013-08-30 16:36:25]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/wangxianzhu@chromium.org/22962004/53001

[commit-bot: I haz the power, 2013-08-30 16:47:27]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-08-30 17:34:39]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/wangxianzhu@chromium.org/22962004/53001

[Xianzhu, 2013-09-03 20:45:55]

Found a fundamental issue of the CL (based on the failures on the try bots
linux_rel and linux_aura). During the async TraceLog flush, if a message loop is
not an actively spinning loop, the flush action scheduled on the thread may be
never executed. For example, the inotify_reader thread on Linux is normally
blocked on RunTask selecting the inotify fds. The thread will block the whole
EndTracing process.

I'm wondering if it's a proper way to add a timeout for the flush task.

[dsinclair, 2013-09-03 21:06:43]

On 2013/09/03 20:45:55, Xianzhu wrote:
> Found a fundamental issue of the CL (based on the failures on the try bots
> linux_rel and linux_aura). During the async TraceLog flush, if a message loop
is
> not an actively spinning loop, the flush action scheduled on the thread may be
> never executed. For example, the inotify_reader thread on Linux is normally
> blocked on RunTask selecting the inotify fds. The thread will block the whole
> EndTracing process.
> 
> I'm wondering if it's a proper way to add a timeout for the flush task.

Does that mean you'd lose all of the trace-events from inotify_reader that
aren't flushed?

[Xianzhu, 2013-09-03 21:40:04]

On 2013/09/03 21:06:43, dsinclair wrote:
> On 2013/09/03 20:45:55, Xianzhu wrote:
> > Found a fundamental issue of the CL (based on the failures on the try bots
> > linux_rel and linux_aura). During the async TraceLog flush, if a message
loop
> is
> > not an actively spinning loop, the flush action scheduled on the thread may
be
> > never executed. For example, the inotify_reader thread on Linux is normally
> > blocked on RunTask selecting the inotify fds. The thread will block the
whole
> > EndTracing process.
> > 
> > I'm wondering if it's a proper way to add a timeout for the flush task.
> 
> Does that mean you'd lose all of the trace-events from inotify_reader that
> aren't flushed?

Yes. Haven't found a solution to the issue.

[Xianzhu, 2013-09-03 22:02:45]

On 2013/09/03 21:40:04, Xianzhu wrote:
> On 2013/09/03 21:06:43, dsinclair wrote:
> > On 2013/09/03 20:45:55, Xianzhu wrote:
> > > Found a fundamental issue of the CL (based on the failures on the try bots
> > > linux_rel and linux_aura). During the async TraceLog flush, if a message
> loop
> > is
> > > not an actively spinning loop, the flush action scheduled on the thread
may
> be
> > > never executed. For example, the inotify_reader thread on Linux is
normally
> > > blocked on RunTask selecting the inotify fds. The thread will block the
> whole
> > > EndTracing process.
> > > 
> > > I'm wondering if it's a proper way to add a timeout for the flush task.
> > 
> > Does that mean you'd lose all of the trace-events from inotify_reader that
> > aren't flushed?
> 
> Yes. Haven't found a solution to the issue.

Actually not always yes. We lose the last batch. If the thread produces
trace-events fewer than 1024, then all events will be lost.

[Xianzhu, 2013-09-03 23:34:20]

PTAL. In the latest patch:
- added timeout when waiting for thread-local flush;
- changed the thread-local buffer size from 1024 to 64 to reduce the number of
unflushed events on timeout. I believe 64 is enough to reduce the overhead of
lock.

[dsinclair, 2013-09-04 14:24:27]

lgtm

[commit-bot: I haz the power, 2013-09-04 19:08:46]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/wangxianzhu@chromium.org/22962004/68001

[commit-bot: I haz the power, 2013-09-06 16:51:27]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/wangxianzhu@chromium.org/22962004/114001

[commit-bot: I haz the power, 2013-09-06 20:18:12]

Change committed as 221766