Ensure GPU logs are not lost during some stages of startup.

Prior to this change there exists a window between when GpuMain()
hands off log collection and when GpuServiceImpl::InitializeWithHost()
starts forwarding to the GpuProcessHost. We have sometimes lost key
debugging logs in these cases.

Now GpuServiceImpl handles collection of GpuMain() logs all the way up
until GpuServiceImpl::InitializeWithHost() takes over, so no logs are
lost during startup.

Fixed: 1065082
Change-Id: I1d0376ca917218cb6cb6c7298ad59021ba6832ad
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2123329
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: danakj <danakj@chromium.org>
Reviewed-by: Zhenyao Mo <zmo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#754614}

components/viz/service/gl/gpu_service_impl.cc

@@ -12,6 +12,7 @@
 #include "base/command_line.h"
 #include "base/feature_list.h"
 #include "base/lazy_instance.h"
+#include "base/no_destructor.h"
 #include "base/task/post_task.h"
 #include "base/task/thread_pool.h"
 #include "base/task_runner_util.h"
@@ -101,9 +102,45 @@ namespace viz {
 
 namespace {
 
-static base::LazyInstance<base::RepeatingCallback<
-    void(int severity, size_t message_start, const std::string& message)>>::
-    Leaky g_log_callback = LAZY_INSTANCE_INITIALIZER;
+static base::LazyInstance<base::RepeatingCallback<void(
+    int severity,
+    const std::string& header,
+    const std::string& message)>>::Leaky g_log_callback =
+    LAZY_INSTANCE_INITIALIZER;
+
+bool GpuLogMessageHandler(int severity,
+                          const char* file,
+                          int line,
+                          size_t message_start,
+                          const std::string& message) {
+  g_log_callback.Get().Run(severity, message.substr(0, message_start),
+                           message.substr(message_start));
+  return false;
+}
+
+struct LogMessage {
+  LogMessage(int severity,
+             const std::string& header,
+             const std::string& message)
+      : severity(severity),
+        header(std::move(header)),
+        message(std::move(message)) {}
+  const int severity;
+  const std::string header;
+  const std::string message;
+};
+
+std::vector<LogMessage>* GetDeferredLogMessages() {
+  static base::NoDestructor<std::vector<LogMessage>> deferred_messages;
+  return deferred_messages.get();
+}
+
+void PreInitializeGlobalLogCallback(int severity,
+                                    const std::string& header,
+                                    const std::string& message) {
+  GetDeferredLogMessages()->emplace_back(severity, std::move(header),
+                                         std::move(message));
+}
 
 bool IsAcceleratedJpegDecodeSupported() {
 #if defined(OS_CHROMEOS)
@@ -114,15 +151,6 @@ bool IsAcceleratedJpegDecodeSupported() {
 #endif  // defined(OS_CHROMEOS)
 }
 
-bool GpuLogMessageHandler(int severity,
-                          const char* file,
-                          int line,
-                          size_t message_start,
-                          const std::string& message) {
-  g_log_callback.Get().Run(severity, message_start, message);
-  return false;
-}
-
 // Returns a callback which does a PostTask to run |callback| on the |runner|
 // task runner.
 template <typename... Params>
@@ -325,6 +353,9 @@ void GpuServiceImpl::InitializeWithHost(
     g_log_callback.Get() = base::BindRepeating(
         &GpuServiceImpl::RecordLogMessage, base::Unretained(this));
     logging::SetLogMessageHandler(GpuLogMessageHandler);
+
+    // Flush any log messages that may have occurred before we took over.
+    FlushPreInitializeLogMessages(gpu_host_.get());
   }
 
   if (!sync_point_manager) {
@@ -404,13 +435,25 @@ gpu::ImageFactory* GpuServiceImpl::gpu_image_factory() {
              : nullptr;
 }
 
+// static
+void GpuServiceImpl::InstallPreInitializeLogHandler() {
+  g_log_callback.Get() = base::BindRepeating(&PreInitializeGlobalLogCallback);
+  logging::SetLogMessageHandler(GpuLogMessageHandler);
+}
+
+// static
+void GpuServiceImpl::FlushPreInitializeLogMessages(mojom::GpuHost* gpu_host) {
+  std::vector<LogMessage>& log_messages = *GetDeferredLogMessages();
+  for (const auto& log : log_messages)
+    gpu_host->RecordLogMessage(log.severity, log.header, log.message);
+  log_messages.clear();
+}
+
 void GpuServiceImpl::RecordLogMessage(int severity,
-                                      size_t message_start,
-                                      const std::string& str) {
+                                      const std::string& header,
+                                      const std::string& message) {
   // This can be run from any thread.
-  std::string header = str.substr(0, message_start);
-  std::string message = str.substr(message_start);
-  gpu_host_->RecordLogMessage(severity, header, message);
+  gpu_host_->RecordLogMessage(severity, std::move(header), std::move(message));
 }
 
 #if defined(OS_CHROMEOS)

components/viz/service/gl/gpu_service_impl.h

@@ -217,6 +217,16 @@ class VIZ_SERVICE_EXPORT GpuServiceImpl : public gpu::GpuChannelManagerDelegate,
                               gpu::SurfaceHandle child_window) override;
 #endif
 
+  // Installs a base::LogMessageHandlerFunction which ensures messages are sent
+  // to the mojom::GpuHost once InitializeWithHost() completes.
+  //
+  // In the event of aborted initialization, FlushPreInitializeLogMessages() may
+  // be called to flush the accumulated logs to the remote host.
+  //
+  // Note: ~GpuServiceImpl() will clear installed log handlers.
+  static void InstallPreInitializeLogHandler();
+  static void FlushPreInitializeLogMessages(mojom::GpuHost* gpu_host);
+
   bool is_initialized() const { return !!gpu_host_; }
 
   media::MediaGpuChannelManager* media_gpu_channel_manager() {
@@ -296,7 +306,7 @@ class VIZ_SERVICE_EXPORT GpuServiceImpl : public gpu::GpuChannelManagerDelegate,
 
  private:
   void RecordLogMessage(int severity,
-                        size_t message_start,
+                        const std::string& header,
                         const std::string& message);
 
   void UpdateGpuInfoPlatform(base::OnceClosure on_gpu_info_updated);

components/viz/service/main/viz_main_impl.cc

@@ -127,10 +127,6 @@ VizMainImpl::~VizMainImpl() {
         dependencies_.ukm_recorder.get());
 }
 
-void VizMainImpl::SetLogMessagesForHost(LogMessages log_messages) {
-  log_messages_ = std::move(log_messages);
-}
-
 void VizMainImpl::BindAssociated(
     mojo::PendingAssociatedReceiver<mojom::VizMain> pending_receiver) {
   receiver_.Bind(std::move(pending_receiver));
@@ -152,11 +148,9 @@ void VizMainImpl::CreateGpuService(
   if (gl::GetGLImplementation() != gl::kGLImplementationDisabled)
     gpu_service_->UpdateGPUInfo();
 
-  for (const LogMessage& log : log_messages_)
-    gpu_host->RecordLogMessage(log.severity, log.header, log.message);
-  log_messages_.clear();
   if (!gpu_init_->init_successful()) {
     LOG(ERROR) << "Exiting GPU process due to errors during initialization";
+    GpuServiceImpl::FlushPreInitializeLogMessages(gpu_host.get());
     gpu_service_.reset();
     gpu_host->DidFailInitialize();
     if (delegate_)

components/viz/service/main/viz_main_impl.h

@@ -45,13 +45,6 @@ class GpuServiceImpl;
 class VizMainImpl : public mojom::VizMain,
                     public gpu::GpuInProcessThreadServiceDelegate {
  public:
-  struct LogMessage {
-    int severity;
-    std::string header;
-    std::string message;
-  };
-  using LogMessages = std::vector<LogMessage>;
-
   class Delegate {
    public:
     virtual ~Delegate() = default;
@@ -105,8 +98,6 @@ class VizMainImpl : public mojom::VizMain,
   // Destruction must happen on the GPU thread.
   ~VizMainImpl() override;
 
-  void SetLogMessagesForHost(LogMessages messages);
-
   void BindAssociated(
       mojo::PendingAssociatedReceiver<mojom::VizMain> pending_receiver);
 
@@ -156,8 +147,6 @@ class VizMainImpl : public mojom::VizMain,
   // destroyed after they are.
   std::unique_ptr<base::Thread> io_thread_;
 
-  LogMessages log_messages_;
-
   std::unique_ptr<gpu::GpuInit> gpu_init_;
   std::unique_ptr<GpuServiceImpl> gpu_service_;
 

content/gpu/gpu_child_thread.cc

@@ -98,13 +98,10 @@ viz::VizMainImpl::ExternalDependencies CreateVizMainDependencies() {
 }  // namespace
 
 GpuChildThread::GpuChildThread(base::RepeatingClosure quit_closure,
-                               std::unique_ptr<gpu::GpuInit> gpu_init,
-                               viz::VizMainImpl::LogMessages log_messages)
+                               std::unique_ptr<gpu::GpuInit> gpu_init)
     : GpuChildThread(std::move(quit_closure),
                      GetOptions(),
-                     std::move(gpu_init)) {
-  viz_main_.SetLogMessagesForHost(std::move(log_messages));
-}
+                     std::move(gpu_init)) {}
 
 GpuChildThread::GpuChildThread(const InProcessChildThreadParams& params,
                                std::unique_ptr<gpu::GpuInit> gpu_init)

content/gpu/gpu_child_thread.h

@@ -48,8 +48,7 @@ class GpuChildThread : public ChildThreadImpl,
                        public viz::VizMainImpl::Delegate {
  public:
   GpuChildThread(base::RepeatingClosure quit_closure,
-                 std::unique_ptr<gpu::GpuInit> gpu_init,
-                 viz::VizMainImpl::LogMessages deferred_messages);
+                 std::unique_ptr<gpu::GpuInit> gpu_init);
 
   GpuChildThread(const InProcessChildThreadParams& params,
                  std::unique_ptr<gpu::GpuInit> gpu_init);

content/gpu/gpu_main.cc

@@ -10,7 +10,6 @@
 
 #include "base/bind.h"
 #include "base/feature_list.h"
-#include "base/lazy_instance.h"
 #include "base/message_loop/message_pump_type.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/rand_util.h"
@@ -118,21 +117,6 @@ bool StartSandboxLinux(gpu::GpuWatchdogThread*,
 bool StartSandboxWindows(const sandbox::SandboxInterfaceInfo*);
 #endif
 
-base::LazyInstance<viz::VizMainImpl::LogMessages>::DestructorAtExit
-    deferred_messages = LAZY_INSTANCE_INITIALIZER;
-
-bool GpuProcessLogMessageHandler(int severity,
-                                 const char* file, int line,
-                                 size_t message_start,
-                                 const std::string& str) {
-  viz::VizMainImpl::LogMessage log;
-  log.severity = severity;
-  log.header = str.substr(0, message_start);
-  log.message = str.substr(message_start);
-  deferred_messages.Get().push_back(std::move(log));
-  return false;
-}
-
 class ContentSandboxHelper : public gpu::GpuSandboxHelper {
  public:
   ContentSandboxHelper() {}
@@ -260,7 +244,9 @@ int GpuMain(const MainFunctionParams& parameters) {
     ::SetPriorityClass(::GetCurrentProcess(), ABOVE_NORMAL_PRIORITY_CLASS);
 #endif
 
-  logging::SetLogMessageHandler(GpuProcessLogMessageHandler);
+  // Installs a base::LogMessageHandlerFunction which ensures messages are sent
+  // to the GpuProcessHost once the GpuServiceImpl has started.
+  viz::GpuServiceImpl::InstallPreInitializeLogHandler();
 
   // We are experiencing what appear to be memory-stomp issues in the GPU
   // process. These issues seem to be impacting the task executor and listeners
@@ -356,7 +342,6 @@ int GpuMain(const MainFunctionParams& parameters) {
       const_cast<base::CommandLine*>(&command_line), gpu_preferences);
   const bool dead_on_arrival = !init_success;
 
-  logging::SetLogMessageHandler(nullptr);
   GetContentClient()->SetGpuInfo(gpu_init->gpu_info());
 
   const base::ThreadPriority io_thread_priority =
@@ -390,10 +375,7 @@ int GpuMain(const MainFunctionParams& parameters) {
 
   base::RunLoop run_loop;
   GpuChildThread* child_thread =
-      new GpuChildThread(run_loop.QuitClosure(), std::move(gpu_init),
-                         std::move(deferred_messages.Get()));
-  deferred_messages.Get().clear();
-
+      new GpuChildThread(run_loop.QuitClosure(), std::move(gpu_init));
   child_thread->Init(start_time);
 
   gpu_process.set_main_thread(child_thread);