Perfetto: Ensure we fully wait for child processes to start tracing

When Perfetto is enabled but used by the legacy Coordinator/Agent
Mojo layer, tracing is enabled through a different set of message
pipes (the Perfetto Consumer/Producer interfaces). To fully ensure
that the legacy Coordinator only calls the BeginTracing callback
when tracing is enabled for all currently running sub-processes,
we add a new API call which explicitly waits for the TraceLog to
become enabled for that sub-process before calling the callback.

This should fix some flaky tests in the perfetto_content_browsertests
suite.

BUG=839084,935642
R=dcheng@chromium.org,eseckler@chromium.org

Change-Id: I0d72cf3f393c5e68d54a489e6c7a17699e02a4e7
Reviewed-on: https://chromium-review.googlesource.com/c/1490901Reviewed-by: Daniel Cheng <dcheng@chromium.org>
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Commit-Queue: oysteine <oysteine@chromium.org>
Cr-Commit-Position: refs/heads/master@{#636441}

base/trace_event/trace_log.h

@@ -151,6 +151,10 @@ class BASE_EXPORT TraceLog : public MemoryDumpProvider {
     // TraceLog::IsEnabled() is false at this point.
     virtual void OnTraceLogDisabled() = 0;
   };
+  // TODO(oysteine): This API originally needed to use WeakPtrs as the observer
+  // list was copied under the global trace lock, but iterated over outside of
+  // that lock so that observers could add tracing. The list is now protected by
+  // its own lock, so this can be changed to a raw ptr.
   void AddAsyncEnabledStateObserver(
       WeakPtr<AsyncEnabledStateObserver> listener);
   void RemoveAsyncEnabledStateObserver(AsyncEnabledStateObserver* listener);

services/tracing/perfetto/perfetto_tracing_coordinator.cc

@@ -256,15 +256,15 @@ void PerfettoTracingCoordinator::PingAgent(
   // system as a fallback when using Perfetto, rather than
   // the browser directly using a Consumer interface, we have to
   // attempt to linearize with newly connected agents so we only
-  // call the BeginTracing callback when we can be fairly sure
+  // call the BeginTracing callback when we can be sure
   // that all current agents have registered with Perfetto and
   // started tracing if requested. We do this linearization
-  // by calling RequestBufferStatus but just throwing away the
-  // result.
+  // explicitly using WaitForTracingEnabled() which will wait
+  // for the TraceLog to be enabled before calling its provided
+  // callback.
   auto closure = base::BindRepeating(
       [](base::WeakPtr<PerfettoTracingCoordinator> coordinator,
-         AgentRegistry::AgentEntry* agent_entry, uint32_t capacity,
-         uint32_t count) {
+         AgentRegistry::AgentEntry* agent_entry) {
         bool removed =
             agent_entry->RemoveDisconnectClosure(GetStartTracingClosureName());
         DCHECK(removed);
@@ -275,10 +275,9 @@ void PerfettoTracingCoordinator::PingAgent(
       },
       weak_factory_.GetWeakPtr(), base::Unretained(agent_entry));
 
-  agent_entry->AddDisconnectClosure(GetStartTracingClosureName(),
-                                    base::BindOnce(closure, 0, 0));
+  agent_entry->AddDisconnectClosure(GetStartTracingClosureName(), closure);
 
-  agent_entry->agent()->RequestBufferStatus(closure);
+  agent_entry->agent()->WaitForTracingEnabled(closure);
   RemoveExpectedPID(agent_entry->pid());
 }
 

services/tracing/public/cpp/base_agent.cc

@@ -51,4 +51,9 @@ void BaseAgent::RequestBufferStatus(
   std::move(callback).Run(0 /* capacity */, 0 /* count */);
 }
 
+void BaseAgent::WaitForTracingEnabled(
+    Agent::WaitForTracingEnabledCallback callback) {
+  std::move(callback).Run();
+}
+
 }  // namespace tracing

services/tracing/public/cpp/base_agent.h

@@ -40,6 +40,8 @@ class COMPONENT_EXPORT(TRACING_CPP) BaseAgent : public mojom::Agent {
   void StopAndFlush(tracing::mojom::RecorderPtr recorder) override;
   void RequestBufferStatus(
       Agent::RequestBufferStatusCallback callback) override;
+  void WaitForTracingEnabled(
+      Agent::WaitForTracingEnabledCallback callback) override;
 
   mojo::Binding<tracing::mojom::Agent> binding_;
 

services/tracing/public/cpp/trace_event_agent.cc

@@ -40,13 +40,19 @@ TraceEventAgent::TraceEventAgent()
     : BaseAgent(kTraceEventLabel,
                 mojom::TraceDataType::ARRAY,
                 base::trace_event::TraceLog::GetInstance()->process_id()),
-      enabled_tracing_modes_(0) {
+      enabled_tracing_modes_(0),
+      weak_ptr_factory_(this) {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
 
+  base::trace_event::TraceLog::GetInstance()->AddAsyncEnabledStateObserver(
+      weak_ptr_factory_.GetWeakPtr());
+
   ProducerClient::Get()->AddDataSource(TraceEventDataSource::GetInstance());
 }
 
-TraceEventAgent::~TraceEventAgent() = default;
+TraceEventAgent::~TraceEventAgent() {
+  DCHECK(!tracing_enabled_callback_);
+}
 
 void TraceEventAgent::GetCategories(std::set<std::string>* category_set) {
   for (size_t i = base::trace_event::BuiltinCategories::kVisibleCategoryStart;
@@ -74,7 +80,9 @@ void TraceEventAgent::AddMetadataGeneratorFunction(
 void TraceEventAgent::StartTracing(const std::string& config,
                                    base::TimeTicks coordinator_time,
                                    StartTracingCallback callback) {
+  DCHECK(!TracingUsesPerfettoBackend());
   DCHECK(!recorder_);
+  DCHECK(!tracing_enabled_callback_);
 #if defined(__native_client__)
   // NaCl and system times are offset by a bit, so subtract some time from
   // the captured timestamps. The value might be off by a bit due to messaging
@@ -92,6 +100,7 @@ void TraceEventAgent::StartTracing(const std::string& config,
 }
 
 void TraceEventAgent::StopAndFlush(mojom::RecorderPtr recorder) {
+  DCHECK(!TracingUsesPerfettoBackend());
   DCHECK(!recorder_);
 
   recorder_ = std::move(recorder);
@@ -110,11 +119,36 @@ void TraceEventAgent::StopAndFlush(mojom::RecorderPtr recorder) {
 
 void TraceEventAgent::RequestBufferStatus(
     RequestBufferStatusCallback callback) {
+  DCHECK(!TracingUsesPerfettoBackend());
   base::trace_event::TraceLogStatus status =
       base::trace_event::TraceLog::GetInstance()->GetStatus();
   std::move(callback).Run(status.event_capacity, status.event_count);
 }
 
+void TraceEventAgent::WaitForTracingEnabled(
+    Agent::WaitForTracingEnabledCallback callback) {
+  DCHECK(TracingUsesPerfettoBackend());
+  DCHECK(!tracing_enabled_callback_);
+  if (base::trace_event::TraceLog::GetInstance()->IsEnabled()) {
+    std::move(callback).Run();
+    return;
+  }
+
+  tracing_enabled_callback_ = std::move(callback);
+}
+
+// This callback will always come on the same sequence
+// that TraceLog::AddAsyncEnabledStateObserver was called
+// on to begin with, i.e. the same as any WaitForTracingEnabled()
+// calls are run on.
+void TraceEventAgent::OnTraceLogEnabled() {
+  if (tracing_enabled_callback_) {
+    std::move(tracing_enabled_callback_).Run();
+  }
+}
+
+void TraceEventAgent::OnTraceLogDisabled() {}
+
 void TraceEventAgent::OnTraceLogFlush(
     const scoped_refptr<base::RefCountedString>& events_str,
     bool has_more_events) {

services/tracing/public/cpp/trace_event_agent.h

@@ -13,7 +13,9 @@
 #include "base/component_export.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/ref_counted_memory.h"
+#include "base/memory/weak_ptr.h"
 #include "base/threading/thread_checker.h"
+#include "base/trace_event/trace_log.h"
 #include "base/values.h"
 #include "services/tracing/public/cpp/base_agent.h"
 #include "services/tracing/public/mojom/tracing.mojom.h"
@@ -29,7 +31,9 @@ namespace tracing {
 // most of the mojom::Agent functions will never be used
 // as the control signals will go through the Perfetto
 // interface instead.
-class COMPONENT_EXPORT(TRACING_CPP) TraceEventAgent : public BaseAgent {
+class COMPONENT_EXPORT(TRACING_CPP) TraceEventAgent
+    : public BaseAgent,
+      public base::trace_event::TraceLog::AsyncEnabledStateObserver {
  public:
   static TraceEventAgent* GetInstance();
 
@@ -57,13 +61,20 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventAgent : public BaseAgent {
 
   void OnTraceLogFlush(const scoped_refptr<base::RefCountedString>& events_str,
                        bool has_more_events);
+  void WaitForTracingEnabled(
+      Agent::WaitForTracingEnabledCallback callback) override;
+
+  // base::trace_event::TraceLog::AsyncEnabledStateObserver
+  void OnTraceLogEnabled() override;
+  void OnTraceLogDisabled() override;
 
   uint8_t enabled_tracing_modes_;
   mojom::RecorderPtr recorder_;
   std::vector<MetadataGeneratorFunction> metadata_generator_functions_;
+  Agent::WaitForTracingEnabledCallback tracing_enabled_callback_;
 
   THREAD_CHECKER(thread_checker_);
-
+  base::WeakPtrFactory<TraceEventAgent> weak_ptr_factory_;
   DISALLOW_COPY_AND_ASSIGN(TraceEventAgent);
 };
 

services/tracing/public/mojom/tracing.mojom

@@ -43,6 +43,16 @@ interface Agent {
       => (bool success);
   StopAndFlush(Recorder recorder);
   RequestBufferStatus() => (uint32 capacity, uint32 count);
+  // This is only ever needed when the legacy Coordinator uses Perfetto to
+  // start tracing, rather than calling StartTracing on each agent through
+  // this interface. In that case, the Coordinator still needs a way of
+  // deferring the success callback until we know that tracing has started
+  // in each relevant process. This is a temporary thing until all clients
+  // of the TracingController in the browser (which uses the
+  // Coordinator interface) have been migrated to use the Perfetto
+  // Consumer interface directly instead, and the Coordinator/Agent
+  // interfaces can be removed.
+  WaitForTracingEnabled() => ();
 };
 
 // An agent can make several calls to |AddChunk|. Chunks will be concatenated

services/tracing/test_util.cc

@@ -5,6 +5,7 @@
 #include "services/tracing/test_util.h"
 
 #include <string>
+#include <utility>
 
 #include "services/tracing/public/mojom/tracing.mojom.h"
 
@@ -42,4 +43,9 @@ void MockAgent::RequestBufferStatus(RequestBufferStatusCallback cb) {
                     trace_log_status_.event_count);
 }
 
+void MockAgent::WaitForTracingEnabled(
+    Agent::WaitForTracingEnabledCallback callback) {
+  std::move(callback).Run();
+}
+
 }  // namespace tracing

services/tracing/test_util.h

@@ -41,6 +41,8 @@ class MockAgent : public mojom::Agent {
                     StartTracingCallback cb) override;
   void StopAndFlush(mojom::RecorderPtr recorder) override;
   void RequestBufferStatus(RequestBufferStatusCallback cb) override;
+  void WaitForTracingEnabled(
+      Agent::WaitForTracingEnabledCallback callback) override;
 
   mojo::Binding<mojom::Agent> binding_;
   std::vector<std::string> call_stat_;