Ensure that aborting startup tracing stops tracing

Startup tracing started by flags can be aborted or sometimes never owned
if the service doesn’t request. In this case tracing must be stopped in
all processes. So, set a timeout for 10 seconds and cancel tracing if no
clients claim the trace data.

Change-Id: I330491382c8c6973d9763db92a814ab8a9b7920d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1666694Reviewed-by: Alex Moshchuk <alexmos@chromium.org>
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Commit-Queue: ssid <ssid@chromium.org>
Cr-Commit-Position: refs/heads/master@{#680133}

content/app/content_main_runner_impl.cc

@@ -918,6 +918,8 @@ int ContentMainRunnerImpl::RunServiceManager(MainFunctionParams& main_params,
       StartBrowserThreadPool();
     }
 
+    tracing::InitTracingPostThreadPoolStart();
+
     BrowserTaskExecutor::PostFeatureListSetup();
 
     delegate_->PostTaskSchedulerStart();

services/tracing/public/cpp/perfetto/perfetto_traced_process.cc

@@ -7,6 +7,7 @@
 #include "base/feature_list.h"
 #include "base/no_destructor.h"
 #include "base/run_loop.h"
+#include "base/sequenced_task_runner.h"
 #include "base/task/post_task.h"
 #include "build/build_config.h"
 #include "services/tracing/public/cpp/perfetto/dummy_producer.h"
@@ -139,8 +140,9 @@ PerfettoTaskRunner* PerfettoTracedProcess::GetTaskRunner() {
 }
 
 // static
-void PerfettoTracedProcess::ResetTaskRunnerForTesting() {
-  GetTaskRunner()->ResetTaskRunnerForTesting(nullptr);
+void PerfettoTracedProcess::ResetTaskRunnerForTesting(
+    scoped_refptr<base::SequencedTaskRunner> task_runner) {
+  GetTaskRunner()->ResetTaskRunnerForTesting(task_runner);
   // Detaching the sequence_checker_ must happen after we reset the task runner.
   // This is because the Get() could call the constructor (if this is the first
   // call to Get()) which would then PostTask which would create races if we

services/tracing/public/cpp/perfetto/perfetto_traced_process.h

@@ -7,6 +7,7 @@
 
 #include "base/component_export.h"
 #include "base/sequence_checker.h"
+#include "base/sequenced_task_runner.h"
 #include "services/tracing/public/cpp/perfetto/task_runner.h"
 
 namespace tracing {
@@ -102,7 +103,8 @@ class COMPONENT_EXPORT(TRACING_CPP) PerfettoTracedProcess final {
   // Be careful when using ResetTaskRunnerForTesting. There is a PostTask in the
   // constructor of PerfettoTracedProcess, so before this class is constructed
   // is the only safe time to call this.
-  static void ResetTaskRunnerForTesting();
+  static void ResetTaskRunnerForTesting(
+      scoped_refptr<base::SequencedTaskRunner> task_runner = nullptr);
 
   static void ReconstructForTesting(const char* system_socket);
 

services/tracing/public/cpp/perfetto/trace_event_data_source.cc

@@ -6,6 +6,7 @@
 
 #include <atomic>
 #include <map>
+#include <memory>
 #include <utility>
 
 #include "base/base64.h"
@@ -19,8 +20,12 @@
 #include "base/metrics/statistics_recorder.h"
 #include "base/no_destructor.h"
 #include "base/pickle.h"
+#include "base/sequence_checker.h"
 #include "base/task/common/scoped_defer_task_posting.h"
+#include "base/threading/sequenced_task_runner_handle.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
+#include "base/trace_event/trace_log.h"
 #include "components/tracing/common/tracing_switches.h"
 #include "services/tracing/public/cpp/perfetto/perfetto_producer.h"
 #include "services/tracing/public/cpp/perfetto/perfetto_traced_process.h"
@@ -235,6 +240,7 @@ TraceEventDataSource::TraceEventDataSource()
       disable_interning_(base::CommandLine::ForCurrentProcess()->HasSwitch(
           switches::kPerfettoDisableInterning)) {
   g_trace_event_data_source_for_testing = this;
+  DETACH_FROM_SEQUENCE(perfetto_sequence_checker_);
 }
 
 TraceEventDataSource::~TraceEventDataSource() = default;
@@ -250,11 +256,19 @@ void TraceEventDataSource::RegisterWithTraceLog() {
 void TraceEventDataSource::UnregisterFromTraceLog() {
   RegisterTracedValueProtoWriter(false);
   TraceLog::GetInstance()->SetAddTraceEventOverrides(nullptr, nullptr, nullptr);
+  base::AutoLock l(lock_);
+  flushing_trace_log_ = false;
+  DCHECK(!flush_complete_task_);
 }
 
 void TraceEventDataSource::SetupStartupTracing(bool privacy_filtering_enabled) {
   {
     base::AutoLock lock(lock_);
+    // Do not enable startup registry if trace log is being flushed. The
+    // previous tracing session has not ended yet.
+    if (flushing_trace_log_) {
+      return;
+    }
     // No need to do anything if startup tracing has already been set,
     // or we know Perfetto has already been setup.
     if (startup_writer_registry_ || producer_) {
@@ -267,11 +281,97 @@ void TraceEventDataSource::SetupStartupTracing(bool privacy_filtering_enabled) {
         std::make_unique<perfetto::StartupTraceWriterRegistry>();
   }
   RegisterWithTraceLog();
+  if (base::SequencedTaskRunnerHandle::IsSet()) {
+    OnTaskSchedulerAvailable();
+  }
+}
+
+void TraceEventDataSource::OnTaskSchedulerAvailable() {
+  {
+    base::AutoLock lock(lock_);
+    if (!startup_writer_registry_)
+      return;
+  }
+  startup_tracing_timer_.Start(
+      FROM_HERE, startup_tracing_timeout_,
+      base::BindOnce(&TraceEventDataSource::StartupTracingTimeoutFired,
+                     base::Unretained(this)));
+}
+
+void TraceEventDataSource::StartupTracingTimeoutFired() {
+  auto task_runner =
+      PerfettoTracedProcess::Get()->GetTaskRunner()->GetOrCreateTaskRunner();
+  if (!task_runner->RunsTasksInCurrentSequence()) {
+    task_runner->PostTask(
+        FROM_HERE,
+        base::BindOnce(&TraceEventDataSource::StartupTracingTimeoutFired,
+                       base::Unretained(this)));
+    return;
+  }
+  DCHECK_CALLED_ON_VALID_SEQUENCE(perfetto_sequence_checker_);
+  std::unique_ptr<perfetto::StartupTraceWriterRegistry> registry;
+  {
+    base::AutoLock lock(lock_);
+    if (!startup_writer_registry_) {
+      return;
+    }
+    // Set startup_writer_registry_ to null so that no further writers are
+    // created.
+    startup_writer_registry_.reset();
+    flushing_trace_log_ = true;
+  }
+  auto* trace_log = base::trace_event::TraceLog::GetInstance();
+  trace_log->SetDisabled();
+  trace_log->Flush(base::BindRepeating(&TraceEventDataSource::OnFlushFinished,
+                                       base::Unretained(this)),
+                   /*use_worker_thread=*/false);
+}
+
+void TraceEventDataSource::OnFlushFinished(
+    const scoped_refptr<base::RefCountedString>&,
+    bool has_more_events) {
+  if (has_more_events) {
+    return;
+  }
+
+  // Clear the pending task on the tracing service thread.
+  DCHECK_CALLED_ON_VALID_SEQUENCE(perfetto_sequence_checker_);
+  base::OnceClosure task;
+  {
+    base::AutoLock l(lock_);
+    // Run any pending start or stop tracing
+    // task.
+    task = std::move(flush_complete_task_);
+    flushing_trace_log_ = false;
+  }
+  if (task) {
+    std::move(task).Run();
+  }
 }
 
 void TraceEventDataSource::StartTracing(
     PerfettoProducer* producer,
     const perfetto::DataSourceConfig& data_source_config) {
+  {
+    base::AutoLock l(lock_);
+    if (flushing_trace_log_) {
+      DCHECK(!flush_complete_task_);
+      // Delay start tracing until flush is finished.
+      // Unretained is fine here because the producer will be valid till
+      // stop tracing is called and at stop this task will be cleared.
+      flush_complete_task_ = base::BindOnce(
+          &TraceEventDataSource::StartTracingInternal, base::Unretained(this),
+          base::Unretained(producer), data_source_config);
+      return;
+    }
+  }
+  StartTracingInternal(producer, data_source_config);
+}
+
+void TraceEventDataSource::StartTracingInternal(
+    PerfettoProducer* producer,
+    const perfetto::DataSourceConfig& data_source_config) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(perfetto_sequence_checker_);
   std::unique_ptr<perfetto::StartupTraceWriterRegistry> unbound_writer_registry;
   {
     base::AutoLock lock(lock_);
@@ -312,7 +412,7 @@ void TraceEventDataSource::StartTracing(
 
 void TraceEventDataSource::StopTracing(
     base::OnceClosure stop_complete_callback) {
-  LogHistograms();
+  DCHECK_CALLED_ON_VALID_SEQUENCE(perfetto_sequence_checker_);
   stop_complete_callback_ = std::move(stop_complete_callback);
 
   auto on_tracing_stopped_callback =
@@ -332,15 +432,28 @@ void TraceEventDataSource::StopTracing(
   bool was_enabled = TraceLog::GetInstance()->IsEnabled();
   if (was_enabled) {
     // Write metadata events etc.
+    LogHistograms();
     TraceLog::GetInstance()->SetDisabled();
   }
 
   {
-    // Prevent recreation of ThreadLocalEventSinks after flush.
     base::AutoLock lock(lock_);
+    if (flush_complete_task_) {
+      DCHECK(!producer_);
+      // Skip start tracing task at this point if we still have not flushed
+      // trace log. We wouldn't be replacing a |flush_complete_task_| that is
+      // stop tracing callback task at any point, since perfetto will wait for
+      // the callback before starting next session.
+      flush_complete_task_ =
+          base::BindOnce(std::move(on_tracing_stopped_callback), this,
+                         scoped_refptr<base::RefCountedString>(), false);
+      return;
+    }
+    // Prevent recreation of ThreadLocalEventSinks after flush.
     DCHECK(producer_);
     producer_ = nullptr;
     target_buffer_ = 0;
+    flushing_trace_log_ = was_enabled;
   }
 
   if (was_enabled) {

services/tracing/public/cpp/perfetto/trace_event_data_source.h

@@ -13,8 +13,10 @@
 #include "base/component_export.h"
 #include "base/macros.h"
 #include "base/metrics/histogram_base.h"
+#include "base/sequence_checker.h"
 #include "base/threading/thread_local.h"
 #include "base/time/time.h"
+#include "base/timer/timer.h"
 #include "base/trace_event/trace_config.h"
 #include "services/tracing/public/cpp/perfetto/perfetto_traced_process.h"
 #include "third_party/perfetto/protos/perfetto/trace/chrome/chrome_metadata.pbzero.h"
@@ -114,6 +116,8 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
   // service. Should only be called once.
   void SetupStartupTracing(bool privacy_filtering_enabled);
 
+  void OnTaskSchedulerAvailable();
+
   // The PerfettoProducer is responsible for calling StopTracing
   // which will clear the stored pointer to it, before it
   // gets destroyed. PerfettoProducer::CreateTraceWriter can be
@@ -131,12 +135,24 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
   void ReturnTraceWriter(
       std::unique_ptr<perfetto::StartupTraceWriter> trace_writer);
 
+  void set_startup_tracing_timeout_for_testing(base::TimeDelta timeout_us) {
+    startup_tracing_timeout_ = timeout_us;
+  }
+
  private:
   friend class base::NoDestructor<TraceEventDataSource>;
 
   TraceEventDataSource();
   ~TraceEventDataSource() override;
 
+  void StartupTracingTimeoutFired();
+  void OnFlushFinished(const scoped_refptr<base::RefCountedString>&,
+                       bool has_more_events);
+
+  void StartTracingInternal(
+      PerfettoProducer* producer_client,
+      const perfetto::DataSourceConfig& data_source_config);
+
   void RegisterWithTraceLog();
   void UnregisterFromTraceLog();
 
@@ -167,6 +183,7 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
   // This ID is incremented whenever a new tracing session is started.
   static constexpr uint32_t kInvalidSessionID = 0;
   static constexpr uint32_t kFirstSessionID = 1;
+  base::TimeDelta startup_tracing_timeout_ = base::TimeDelta::FromSeconds(10);
   std::atomic<uint32_t> session_id_{kInvalidSessionID};
 
   // To avoid lock-order inversion, this lock should not be held while making
@@ -180,8 +197,12 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
   // SetupStartupTracing() is called.
   std::unique_ptr<perfetto::StartupTraceWriterRegistry>
       startup_writer_registry_;
+  base::OneShotTimer startup_tracing_timer_;
+  bool flushing_trace_log_ = false;
+  base::OnceClosure flush_complete_task_;
   std::vector<std::string> histograms_;
   bool privacy_filtering_enabled_ = false;
+  SEQUENCE_CHECKER(perfetto_sequence_checker_);
 
   DISALLOW_COPY_AND_ASSIGN(TraceEventDataSource);
 };

services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

@@ -5,6 +5,7 @@
 #include "services/tracing/public/cpp/perfetto/trace_event_data_source.h"
 
 #include <map>
+#include <memory>
 #include <utility>
 #include <vector>
 
@@ -15,10 +16,16 @@
 #include "base/json/json_reader.h"
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
+#include "base/synchronization/waitable_event.h"
+#include "base/task/post_task.h"
 #include "base/test/scoped_task_environment.h"
+#include "base/threading/sequenced_task_runner_handle.h"
 #include "base/threading/thread_id_name_manager.h"
+#include "base/threading/thread_restrictions.h"
+#include "base/time/time.h"
 #include "base/trace_event/thread_instruction_count.h"
 #include "base/trace_event/trace_event.h"
+#include "base/trace_event/trace_log.h"
 #include "components/tracing/common/tracing_switches.h"
 #include "services/tracing/public/cpp/perfetto/producer_client.h"
 #include "services/tracing/public/mojom/perfetto_service.mojom.h"
@@ -118,6 +125,11 @@ class MockProducerClient : public ProducerClient {
     return &proto_metadata_packets_[packet_index]->chrome_metadata();
   }
 
+  const std::vector<std::unique_ptr<perfetto::protos::TracePacket>>&
+  finalized_packets() {
+    return finalized_packets_;
+  }
+
  private:
   std::vector<std::unique_ptr<perfetto::protos::TracePacket>>
       finalized_packets_;
@@ -1139,6 +1151,80 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) {
   ExpectDebugAnnotationNames(e_packet3, {{1u, "arg2"}});
 }
 
+TEST_F(TraceEventDataSourceTest, StartupTracingTimeout) {
+  PerfettoTracedProcess::ResetTaskRunnerForTesting(
+      base::SequencedTaskRunnerHandle::Get());
+  constexpr char kStartupTestEvent1[] = "startup_registry";
+  TraceEventDataSource::ResetForTesting();
+  auto* data_source = TraceEventDataSource::GetInstance();
+
+  // Start startup tracing registry with no timeout. This would cause startup
+  // tracing to abort and flush as soon the current thread can run tasks.
+  data_source->set_startup_tracing_timeout_for_testing(base::TimeDelta());
+  data_source->SetupStartupTracing(true);
+  base::trace_event::TraceLog::GetInstance()->SetEnabled(
+      base::trace_event::TraceConfig(),
+      base::trace_event::TraceLog::RECORDING_MODE);
+
+  // The trace event will be added to the startup registry since the abort is
+  // not run yet.
+  TRACE_EVENT_BEGIN0(kCategoryGroup, kStartupTestEvent1);
+
+  // Run task on background thread to add trace events while aborting and
+  // starting tracing on the data source. This is to test we do not have any
+  // crashes when a background thread is trying to create trace writers when
+  // deleting startup registry and setting the producer.
+  auto wait_for_start_tracing = std::make_unique<base::WaitableEvent>();
+  base::WaitableEvent* wait_ptr = wait_for_start_tracing.get();
+  base::PostTaskWithTraits(
+      FROM_HERE, base::TaskPriority::BEST_EFFORT,
+      base::BindOnce(
+          [](std::unique_ptr<base::WaitableEvent> wait_for_start_tracing) {
+            // This event can be hit anytime before startup registry is
+            // destroyed to tracing started using producer.
+            TRACE_EVENT_BEGIN0(kCategoryGroup, "maybe_lost");
+            base::ScopedAllowBaseSyncPrimitivesForTesting allow;
+            wait_for_start_tracing->Wait();
+            // This event can be hit while flushing for startup registry or when
+            // tracing is started or when already stopped tracing.
+            TRACE_EVENT_BEGIN0(kCategoryGroup, "maybe_lost");
+          },
+          std::move(wait_for_start_tracing)));
+
+  // Let tasks run on this thread, which should abort startup tracing and flush
+  // since we have not added a producer to the data source.
+  data_source->OnTaskSchedulerAvailable();
+  base::RunLoop().RunUntilIdle();
+  ASSERT_FALSE(base::trace_event::TraceLog::GetInstance()->IsEnabled());
+
+  // Start tracing while flush is running.
+  perfetto::DataSourceConfig config;
+  data_source->StartTracing(producer_client(), config);
+  wait_ptr->Signal();
+
+  // Verify that the trace buffer does not have the event added to startup
+  // registry.
+  producer_client()->FlushPacketIfPossible();
+  std::set<std::string> event_names;
+  for (const auto& packet : producer_client()->finalized_packets()) {
+    if (packet->has_interned_data()) {
+      for (const auto& name : packet->interned_data().legacy_event_names()) {
+        event_names.insert(name.name());
+      }
+    }
+  }
+  EXPECT_EQ(event_names.end(), event_names.find(kStartupTestEvent1));
+
+  // Stop tracing must be called even if tracing is not started to clear the
+  // pending task.
+  base::RunLoop wait_for_stop;
+  data_source->StopTracing(base::BindRepeating(
+      [](const base::RepeatingClosure& quit_closure) { quit_closure.Run(); },
+      wait_for_stop.QuitClosure()));
+
+  wait_for_stop.Run();
+}
+
 // TODO(eseckler): Add startup tracing unittests.
 
 }  // namespace

services/tracing/public/cpp/trace_startup.cc

@@ -61,4 +61,8 @@ void EnableStartupTracingIfNeeded() {
   }
 }
 
+void InitTracingPostThreadPoolStart() {
+  TraceEventDataSource::GetInstance()->OnTaskSchedulerAvailable();
+}
+
 }  // namespace tracing

services/tracing/public/cpp/trace_startup.h

@@ -15,6 +15,9 @@ namespace tracing {
 // tracing backend is used.
 void COMPONENT_EXPORT(TRACING_CPP) EnableStartupTracingIfNeeded();
 
+// Initialize tracing components that require task runners.
+void COMPONENT_EXPORT(TRACING_CPP) InitTracingPostThreadPoolStart();
+
 }  // namespace tracing
 
 #endif  // SERVICES_TRACING_PUBLIC_CPP_TRACE_STARTUP_H_