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)

Review URL: https://chromiumcodereview.appspot.com/22962004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@221766 0039d316-1c4b-4281-b951-d872f2087c98

2 files changed, 17 insertions, 12 deletions

diff --git a/components/tracing/child_trace_message_filter.cc b/components/tracing/child_trace_message_filter.cc
index 154903a..8310ec5 100644
--- a/components/tracing/child_trace_message_filter.cc
+++ b/components/tracing/child_trace_message_filter.cc
@@ -65,16 +65,12 @@ void ChildTraceMessageFilter::OnBeginTracing(
 void ChildTraceMessageFilter::OnEndTracing() {
   TraceLog::GetInstance()->SetDisabled();
 
-  // Flush will generate one or more callbacks to OnTraceDataCollected. It's
-  // important that the last OnTraceDataCollected gets called before
-  // EndTracingAck below. We are already on the IO thread, so the
+  // Flush will generate one or more callbacks to OnTraceDataCollected
+  // synchronously or asynchronously. EndTracingAck will be sent in the last
+  // OnTraceDataCollected. We are already on the IO thread, so the
   // OnTraceDataCollected calls will not be deferred.
   TraceLog::GetInstance()->Flush(
       base::Bind(&ChildTraceMessageFilter::OnTraceDataCollected, this));
-
-  std::vector<std::string> category_groups;
-  TraceLog::GetInstance()->GetKnownCategoryGroups(&category_groups);
-  channel_->Send(new TracingHostMsg_EndTracingAck(category_groups));
 }
 
 void ChildTraceMessageFilter::OnGetTraceBufferPercentFull() {
@@ -94,15 +90,23 @@ void ChildTraceMessageFilter::OnCancelWatchEvent() {
 }
 
 void ChildTraceMessageFilter::OnTraceDataCollected(
-    const scoped_refptr<base::RefCountedString>& events_str_ptr) {
+    const scoped_refptr<base::RefCountedString>& events_str_ptr,
+    bool has_more_events) {
   if (!ipc_message_loop_->BelongsToCurrentThread()) {
     ipc_message_loop_->PostTask(FROM_HERE,
         base::Bind(&ChildTraceMessageFilter::OnTraceDataCollected, this,
-                   events_str_ptr));
+                   events_str_ptr, has_more_events));
     return;
   }
-  channel_->Send(new TracingHostMsg_TraceDataCollected(
-      events_str_ptr->data()));
+  if (events_str_ptr->data().size()) {
+    channel_->Send(new TracingHostMsg_TraceDataCollected(
+        events_str_ptr->data()));
+  }
+  if (!has_more_events) {
+    std::vector<std::string> category_groups;
+    TraceLog::GetInstance()->GetKnownCategoryGroups(&category_groups);
+    channel_->Send(new TracingHostMsg_EndTracingAck(category_groups));
+  }
 }
 
 void ChildTraceMessageFilter::OnTraceNotification(int notification) {
diff --git a/components/tracing/child_trace_message_filter.h b/components/tracing/child_trace_message_filter.h
index 9631ced..9f10b4a 100644
--- a/components/tracing/child_trace_message_filter.h
+++ b/components/tracing/child_trace_message_filter.h
@@ -41,7 +41,8 @@ class ChildTraceMessageFilter : public IPC::ChannelProxy::MessageFilter {
 
   // Callback from trace subsystem.
   void OnTraceDataCollected(
-      const scoped_refptr<base::RefCountedString>& events_str_ptr);
+      const scoped_refptr<base::RefCountedString>& events_str_ptr,
+      bool has_more_events);
   void OnTraceNotification(int notification);
 
   IPC::Channel* channel_;