Adds a callback to TracingAgent::StartAgentTracing()

This allows us to use tracing agents that require more time to start.
The first use case of this will be the BattOr tracing agent, which
requires several round trips over USB before it can know whether
StartTracing was successful.

Review URL: https://codereview.chromium.org/1614063005

Cr-Commit-Position: refs/heads/master@{#371637}

base/trace_event/tracing_agent.h

@@ -26,6 +26,8 @@ class TraceConfig;
 // system trace and PowerTracingAgent for BattOr power trace.
 class BASE_EXPORT TracingAgent {
  public:
+  using StartAgentTracingCallback =
+      base::Callback<void(const std::string& agent_name, bool success)>;
   // Passing a null or empty events_str_ptr indicates that no trace data is
   // available for the specified agent.
   using StopAgentTracingCallback = base::Callback<void(
@@ -53,7 +55,8 @@ class BASE_EXPORT TracingAgent {
   virtual std::string GetTraceEventLabel() = 0;
 
   // Starts tracing on the tracing agent with the trace configuration.
-  virtual bool StartAgentTracing(const TraceConfig& trace_config) = 0;
+  virtual void StartAgentTracing(const TraceConfig& trace_config,
+                                 const StartAgentTracingCallback& callback) = 0;
 
   // Stops tracing on the tracing agent. The trace data will be passed back to
   // the TracingController via the callback.

chromeos/dbus/debug_daemon_client.cc

@@ -20,6 +20,7 @@
 #include "base/posix/eintr_wrapper.h"
 #include "base/strings/string_util.h"
 #include "base/task_runner_util.h"
+#include "base/thread_task_runner_handle.h"
 #include "chromeos/dbus/pipe_reader.h"
 #include "dbus/bus.h"
 #include "dbus/message.h"
@@ -206,8 +207,8 @@ class DebugDaemonClientImpl : public DebugDaemonClient {
 
   std::string GetTraceEventLabel() override { return kCrOSTraceLabel; }
 
-  bool StartAgentTracing(
-      const base::trace_event::TraceConfig& trace_config) override {
+  void StartAgentTracing(const base::trace_event::TraceConfig& trace_config,
+                         const StartAgentTracingCallback& callback) override {
     dbus::MethodCall method_call(
         debugd::kDebugdInterface,
         debugd::kSystraceStart);
@@ -220,7 +221,10 @@ class DebugDaemonClientImpl : public DebugDaemonClient {
         dbus::ObjectProxy::TIMEOUT_USE_DEFAULT,
         base::Bind(&DebugDaemonClientImpl::OnStartMethod,
                    weak_ptr_factory_.GetWeakPtr()));
-    return true;
+
+    base::ThreadTaskRunnerHandle::Get()->PostTask(
+        FROM_HERE,
+        base::Bind(callback, GetTracingAgentName(), true /* success */));
   }
 
   void StopAgentTracing(const StopAgentTracingCallback& callback) override {

chromeos/dbus/fake_debug_daemon_client.cc

@@ -57,9 +57,12 @@ std::string FakeDebugDaemonClient::GetTraceEventLabel() {
   return kCrOSTraceLabel;
 }
 
-bool FakeDebugDaemonClient::StartAgentTracing(
-    const base::trace_event::TraceConfig& trace_config) {
-  return true;
+void FakeDebugDaemonClient::StartAgentTracing(
+    const base::trace_event::TraceConfig& trace_config,
+    const StartAgentTracingCallback& callback) {
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE,
+      base::Bind(callback, GetTracingAgentName(), true /* success */));
 }
 
 void FakeDebugDaemonClient::StopAgentTracing(

chromeos/dbus/fake_debug_daemon_client.h

@@ -31,8 +31,8 @@ class CHROMEOS_EXPORT FakeDebugDaemonClient : public DebugDaemonClient {
                     const SetDebugModeCallback& callback) override;
   std::string GetTracingAgentName() override;
   std::string GetTraceEventLabel() override;
-  bool StartAgentTracing(
-      const base::trace_event::TraceConfig& trace_config) override;
+  void StartAgentTracing(const base::trace_event::TraceConfig& trace_config,
+                         const StartAgentTracingCallback& callback) override;
   void StopAgentTracing(const StopAgentTracingCallback& callback) override;
   void SetStopAgentTracingTaskRunner(
       scoped_refptr<base::TaskRunner> task_runner) override;

content/browser/tracing/etw_system_event_consumer_win.cc

@@ -11,6 +11,7 @@
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
 #include "base/strings/stringprintf.h"
+#include "base/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event_impl.h"
 #include "content/public/browser/browser_thread.h"
@@ -49,11 +50,16 @@ std::string EtwSystemEventConsumer::GetTraceEventLabel() {
   return kETWTraceLabel;
 }
 
-bool EtwSystemEventConsumer::StartAgentTracing(
-    const base::trace_event::TraceConfig& trace_config) {
+void EtwSystemEventConsumer::StartAgentTracing(
+    const base::trace_event::TraceConfig& trace_config,
+    const StartAgentTracingCallback& callback) {
   // Activate kernel tracing.
-  if (!StartKernelSessionTracing())
-    return false;
+  if (!StartKernelSessionTracing()) {
+    base::ThreadTaskRunnerHandle::Get()->PostTask(
+        FROM_HERE,
+        base::Bind(callback, GetTracingAgentName(), false /* success */));
+    return;
+  }
 
   // Start the consumer thread and start consuming events.
   thread_.Start();
@@ -62,7 +68,9 @@ bool EtwSystemEventConsumer::StartAgentTracing(
       base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread,
                  base::Unretained(this)));
 
-  return true;
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE,
+      base::Bind(callback, GetTracingAgentName(), true /* success */));
 }
 
 void EtwSystemEventConsumer::StopAgentTracing(

content/browser/tracing/etw_system_event_consumer_win.h

@@ -28,8 +28,8 @@ class EtwSystemEventConsumer
   // base::trace_event::TracingAgent implementation.
   std::string GetTracingAgentName() override;
   std::string GetTraceEventLabel() override;
-  bool StartAgentTracing(
-      const base::trace_event::TraceConfig& trace_config) override;
+  void StartAgentTracing(const base::trace_event::TraceConfig& trace_config,
+                         const StartAgentTracingCallback& callback) override;
   void StopAgentTracing(const StopAgentTracingCallback& callback) override;
 
   // Retrieve the ETW consumer instance.

content/browser/tracing/power_tracing_agent.cc

@@ -4,6 +4,7 @@
 
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
+#include "base/thread_task_runner_handle.h"
 #include "base/trace_event/trace_event_impl.h"
 #include "content/browser/tracing/battor_power_trace_provider.h"
 #include "content/browser/tracing/power_tracing_agent.h"
@@ -37,23 +38,29 @@ std::string PowerTracingAgent::GetTraceEventLabel() {
   return kPowerTraceLabel;
 }
 
-bool PowerTracingAgent::StartAgentTracing(
-    const base::trace_event::TraceConfig& trace_config) {
+void PowerTracingAgent::StartAgentTracing(
+    const base::trace_event::TraceConfig& trace_config,
+    const StartAgentTracingCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
   // TODO(charliea): When system tracing is enabled in about://tracing, it will
   // trigger power tracing. We need a way of checking if BattOr is connected.
   // Currently, IsConnected() always returns false, so that we do not include
   // BattOr trace until it is hooked up.
-  if (!battor_trace_provider_->IsConnected())
-    return false;
-
+  if (!battor_trace_provider_->IsConnected()) {
+    base::ThreadTaskRunnerHandle::Get()->PostTask(
+        FROM_HERE,
+        base::Bind(callback, GetTracingAgentName(), false /* success */));
+    return;
+  }
   thread_.Start();
 
   thread_.task_runner()->PostTask(
       FROM_HERE,
       base::Bind(&PowerTracingAgent::TraceOnThread, base::Unretained(this)));
-  return true;
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE,
+      base::Bind(callback, GetTracingAgentName(), true /* success */));
 }
 
 void PowerTracingAgent::StopAgentTracing(

content/browser/tracing/power_tracing_agent.h

@@ -28,8 +28,8 @@ class PowerTracingAgent : public base::trace_event::TracingAgent {
   std::string GetTracingAgentName() override;
   std::string GetTraceEventLabel() override;
 
-  bool StartAgentTracing(
-      const base::trace_event::TraceConfig& trace_config) override;
+  void StartAgentTracing(const base::trace_event::TraceConfig& trace_config,
+                         const StartAgentTracingCallback& callback) override;
   void StopAgentTracing(const StopAgentTracingCallback& callback) override;
 
   bool SupportsExplicitClockSync() override;

content/browser/tracing/tracing_controller_impl.cc

@@ -10,6 +10,8 @@
 #include "base/macros.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
+#include "base/thread_task_runner_handle.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
 #include "components/tracing/process_metrics_memory_dump_provider.h"
@@ -51,7 +53,9 @@ const char kChromeTracingAgentName[] = "chrome";
 const char kETWTracingAgentName[] = "etw";
 const char kChromeTraceLabel[] = "traceEvents";
 
+const int kStartTracingTimeoutSeconds = 30;
 const int kIssueClockSyncTimeoutSeconds = 30;
+const int kStopTracingRetryTimeMilliseconds = 100;
 
 std::string GetNetworkTypeString() {
   switch (net::NetworkChangeNotifier::GetConnectionType()) {
@@ -145,7 +149,8 @@ TracingController* TracingController::GetInstance() {
 }
 
 TracingControllerImpl::TracingControllerImpl()
-    : pending_stop_tracing_ack_count_(0),
+    : pending_start_tracing_ack_count_(0),
+      pending_stop_tracing_ack_count_(0),
       pending_capture_monitoring_snapshot_ack_count_(0),
       pending_trace_log_status_ack_count_(0),
       maximum_trace_buffer_usage_(0),
@@ -219,6 +224,9 @@ bool TracingControllerImpl::StartTracing(
     return false;
   is_tracing_ = true;
   start_tracing_done_callback_ = callback;
+  start_tracing_trace_config_.reset(
+      new base::trace_event::TraceConfig(trace_config));
+  pending_start_tracing_ack_count_ = 0;
 
 #if defined(OS_ANDROID)
   if (pending_get_categories_done_callback_.is_null())
@@ -226,57 +234,88 @@ bool TracingControllerImpl::StartTracing(
 #endif
 
   if (trace_config.IsSystraceEnabled()) {
-    if (PowerTracingAgent::GetInstance()->StartAgentTracing(trace_config))
-      additional_tracing_agents_.push_back(PowerTracingAgent::GetInstance());
+    PowerTracingAgent::GetInstance()->StartAgentTracing(
+        trace_config,
+        base::Bind(&TracingControllerImpl::OnStartAgentTracingAcked,
+                   base::Unretained(this)));
+    ++pending_start_tracing_ack_count_;
+
 #if defined(OS_CHROMEOS)
     chromeos::DebugDaemonClient* debug_daemon =
         chromeos::DBusThreadManager::Get()->GetDebugDaemonClient();
-    if (debug_daemon && debug_daemon->StartAgentTracing(trace_config)) {
-      debug_daemon->SetStopAgentTracingTaskRunner(
-          BrowserThread::GetBlockingPool());
-      additional_tracing_agents_.push_back(
-          chromeos::DBusThreadManager::Get()->GetDebugDaemonClient());
+    if (debug_daemon) {
+      debug_daemon->StartAgentTracing(
+          trace_config,
+          base::Bind(&TracingControllerImpl::OnStartAgentTracingAcked,
+                     base::Unretained(this)));
+      ++pending_start_tracing_ack_count_;
     }
 #elif defined(OS_WIN)
-    if (EtwSystemEventConsumer::GetInstance()->StartAgentTracing(
-        trace_config)) {
-      additional_tracing_agents_.push_back(
-          EtwSystemEventConsumer::GetInstance());
-    }
+    EtwSystemEventConsumer::GetInstance()->StartAgentTracing(
+        trace_config,
+        base::Bind(&TracingControllerImpl::OnStartAgentTracingAcked,
+                   base::Unretained(this)));
+    ++pending_start_tracing_ack_count_;
 #endif
   }
 
   // TraceLog may have been enabled in startup tracing before threads are ready.
   if (TraceLog::GetInstance()->IsEnabled())
     return true;
-  return StartAgentTracing(trace_config);
+
+  StartAgentTracing(trace_config,
+                    base::Bind(&TracingControllerImpl::OnStartAgentTracingAcked,
+                               base::Unretained(this)));
+  ++pending_start_tracing_ack_count_;
+
+  // Set a deadline to ensure all agents ack within a reasonable time frame.
+  start_tracing_timer_.Start(
+      FROM_HERE, base::TimeDelta::FromSeconds(kStartTracingTimeoutSeconds),
+      base::Bind(&TracingControllerImpl::OnAllTracingAgentsStarted,
+                 base::Unretained(this)));
+
+  return true;
 }
 
-void TracingControllerImpl::OnStartAgentTracingDone(
-    const TraceConfig& trace_config) {
+void TracingControllerImpl::OnAllTracingAgentsStarted() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
   TRACE_EVENT_API_ADD_METADATA_EVENT("IsTimeTicksHighResolution", "value",
                                      base::TimeTicks::IsHighResolution());
-  TRACE_EVENT_API_ADD_METADATA_EVENT("TraceConfig", "value",
-                                     trace_config.AsConvertableToTraceFormat());
+  TRACE_EVENT_API_ADD_METADATA_EVENT(
+      "TraceConfig", "value",
+      start_tracing_trace_config_->AsConvertableToTraceFormat());
 
   // Notify all child processes.
   for (TraceMessageFilterSet::iterator it = trace_message_filters_.begin();
       it != trace_message_filters_.end(); ++it) {
-    it->get()->SendBeginTracing(trace_config);
+    it->get()->SendBeginTracing(*start_tracing_trace_config_);
   }
 
-  if (!start_tracing_done_callback_.is_null()) {
+  if (!start_tracing_done_callback_.is_null())
     start_tracing_done_callback_.Run();
-    start_tracing_done_callback_.Reset();
-  }
+
+  start_tracing_done_callback_.Reset();
+  start_tracing_trace_config_.reset();
 }
 
 bool TracingControllerImpl::StopTracing(
     const scoped_refptr<TraceDataSink>& trace_data_sink) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
+  if (!can_stop_tracing())
+    return false;
+
+  // If we're still waiting to start tracing, try again after a delay.
+  if (start_tracing_timer_.IsRunning()) {
+    base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+        FROM_HERE,
+        base::Bind(base::IgnoreResult(&TracingControllerImpl::StopTracing),
+                   base::Unretained(this), trace_data_sink),
+        base::TimeDelta::FromMilliseconds(kStopTracingRetryTimeMilliseconds));
+    return true;
+  }
+
   if (trace_data_sink) {
     if (TraceLog::GetInstance()->GetCurrentTraceConfig()
         .IsArgumentFilterEnabled()) {
@@ -290,9 +329,6 @@ bool TracingControllerImpl::StopTracing(
     trace_data_sink->AddMetadata(*GenerateTracingMetadataDict().get());
   }
 
-  if (!can_stop_tracing())
-    return false;
-
   trace_data_sink_ = trace_data_sink;
 
   // Issue clock sync marker before actually stopping tracing.
@@ -649,6 +685,51 @@ void TracingControllerImpl::RemoveTraceMessageFilter(
   trace_message_filters_.erase(trace_message_filter);
 }
 
+void TracingControllerImpl::AddTracingAgent(const std::string& agent_name) {
+#if defined(OS_CHROMEOS)
+  auto debug_daemon =
+      chromeos::DBusThreadManager::Get()->GetDebugDaemonClient();
+  if (agent_name == debug_daemon->GetTracingAgentName()) {
+    additional_tracing_agents_.push_back(debug_daemon);
+    debug_daemon->SetStopAgentTracingTaskRunner(
+        BrowserThread::GetBlockingPool());
+    return;
+  }
+#elif defined(OS_WIN)
+  auto etw_agent = EtwSystemEventConsumer::GetInstance();
+  if (agent_name == etw_agent->GetTracingAgentName()) {
+    additional_tracing_agents_.push_back(etw_agent);
+    return;
+  }
+#endif
+
+  auto power_agent = PowerTracingAgent::GetInstance();
+  if (agent_name == power_agent->GetTracingAgentName()) {
+    additional_tracing_agents_.push_back(power_agent);
+    return;
+  }
+
+  DCHECK(agent_name == kChromeTracingAgentName);
+}
+
+void TracingControllerImpl::OnStartAgentTracingAcked(
+    const std::string& agent_name,
+    bool success) {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+
+  // Don't taken any further action if the ack came after the deadline.
+  if (!start_tracing_timer_.IsRunning())
+    return;
+
+  if (success)
+    AddTracingAgent(agent_name);
+
+  if (--pending_start_tracing_ack_count_ == 0) {
+    start_tracing_timer_.Stop();
+    OnAllTracingAgentsStarted();
+  }
+}
+
 void TracingControllerImpl::OnStopTracingAcked(
     TraceMessageFilter* trace_message_filter,
     const std::vector<std::string>& known_category_groups) {
@@ -890,28 +971,25 @@ std::string TracingControllerImpl::GetTraceEventLabel() {
   return kChromeTraceLabel;
 }
 
-bool TracingControllerImpl::StartAgentTracing(
-    const base::trace_event::TraceConfig& trace_config) {
+void TracingControllerImpl::StartAgentTracing(
+    const base::trace_event::TraceConfig& trace_config,
+    const StartAgentTracingCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
-  base::Closure on_start_tracing_done_callback =
-      base::Bind(&TracingControllerImpl::OnStartAgentTracingDone,
-                 base::Unretained(this), trace_config);
+  base::Closure on_agent_started =
+      base::Bind(callback, kChromeTracingAgentName, true);
   if (!BrowserThread::PostTask(
           BrowserThread::FILE, FROM_HERE,
           base::Bind(&TracingControllerImpl::SetEnabledOnFileThread,
                      base::Unretained(this), trace_config,
                      base::trace_event::TraceLog::RECORDING_MODE,
-                     on_start_tracing_done_callback))) {
+                     on_agent_started))) {
     // BrowserThread::PostTask fails if the threads haven't been created yet,
     // so it should be safe to just use TraceLog::SetEnabled directly.
     base::trace_event::TraceLog::GetInstance()->SetEnabled(
         trace_config, base::trace_event::TraceLog::RECORDING_MODE);
-    BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
-                            on_start_tracing_done_callback);
+    BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, on_agent_started);
   }
-
-  return true;
 }
 
 void TracingControllerImpl::StopAgentTracing(

content/browser/tracing/tracing_controller_impl.h

@@ -65,8 +65,8 @@ class TracingControllerImpl
   // base::trace_event::TracingAgent implementation.
   std::string GetTracingAgentName() override;
   std::string GetTraceEventLabel() override;
-  bool StartAgentTracing(
-      const base::trace_event::TraceConfig& trace_config) override;
+  void StartAgentTracing(const base::trace_event::TraceConfig& trace_config,
+                         const StartAgentTracingCallback& callback) override;
   void StopAgentTracing(const StopAgentTracingCallback& callback) override;
   bool SupportsExplicitClockSync() override;
   void RecordClockSyncMarker(
@@ -136,6 +136,12 @@ class TracingControllerImpl
       const scoped_refptr<base::RefCountedString>& events_str_ptr,
       bool has_more_events);
 
+  // Adds the tracing agent with the specified agent name to the list of
+  // additional tracing agents.
+  void AddTracingAgent(const std::string& agent_name);
+
+  void OnStartAgentTracingAcked(const std::string& agent_name, bool success);
+
   void OnStopTracingAcked(
       TraceMessageFilter* trace_message_filter,
       const std::vector<std::string>& known_category_groups);
@@ -166,8 +172,7 @@ class TracingControllerImpl
       int mode,
       const base::Closure& callback);
   void SetDisabledOnFileThread(const base::Closure& callback);
-  void OnStartAgentTracingDone(
-      const base::trace_event::TraceConfig& trace_config);
+  void OnAllTracingAgentsStarted();
   void StopTracingAfterClockSync();
   void OnStopTracingDone();
   void OnStartMonitoringDone(
@@ -188,6 +193,12 @@ class TracingControllerImpl
   typedef std::set<scoped_refptr<TraceMessageFilter>> TraceMessageFilterSet;
   TraceMessageFilterSet trace_message_filters_;
 
+  // Pending acks for StartTracing.
+  int pending_start_tracing_ack_count_;
+  base::OneShotTimer start_tracing_timer_;
+  StartTracingDoneCallback start_tracing_done_callback_;
+  scoped_ptr<base::trace_event::TraceConfig> start_tracing_trace_config_;
+
   // Pending acks for StopTracing.
   int pending_stop_tracing_ack_count_;
   TraceMessageFilterSet pending_stop_tracing_filters_;
@@ -209,7 +220,6 @@ class TracingControllerImpl
   uint64_t pending_memory_dump_guid_;
   base::trace_event::MemoryDumpCallback pending_memory_dump_callback_;
 
-  StartTracingDoneCallback start_tracing_done_callback_;
   std::vector<base::trace_event::TracingAgent*> additional_tracing_agents_;
   int clock_sync_id_;
   int pending_clock_sync_ack_count_;