Add GpuBlockedBetweenSwapsUs and SwapTimeUs metrics

This CL adds two metrics for display compositing.
GpuBlockedBetweenSwapsUs: Measures amount of time Gpu Main thread was
blocked during executing tasks for current frame.

SwapTimeUs: Measures time of glSwapBuffers call to evaluate if the
most blocking happens inside swap buffers or at different time

Change-Id: I089c5dbadabb53b128fcb043d9000521a873fefc
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1876911
Commit-Queue: Vasiliy Telezhnikov <vasilyt@chromium.org>
Reviewed-by: kylechar <kylechar@chromium.org>
Reviewed-by: Jonathan Backer <backer@chromium.org>
Reviewed-by: Bo <boliu@chromium.org>
Reviewed-by: Brian White <bcwhite@chromium.org>
Cr-Commit-Position: refs/heads/master@{#711398}

android_webview/browser/gfx/skia_output_surface_dependency_webview.cc

@@ -126,4 +126,10 @@ void SkiaOutputSurfaceDependencyWebView::DidLoseContext(
   LOG(ERROR) << "SkiaRenderer detected lost context.";
 }
 
+base::TimeDelta
+SkiaOutputSurfaceDependencyWebView::GetGpuBlockedTimeSinceLastSwap() {
+  // WebView doesn't track how long GPU thread was blocked
+  return base::TimeDelta();
+}
+
 }  // namespace android_webview

android_webview/browser/gfx/skia_output_surface_dependency_webview.h

@@ -49,6 +49,8 @@ class SkiaOutputSurfaceDependencyWebView
                       gpu::error::ContextLostReason reason,
                       const GURL& active_url) override;
 
+  base::TimeDelta GetGpuBlockedTimeSinceLastSwap() override;
+
  private:
   gl::GLSurface* const gl_surface_;
   TaskQueueWebView* task_queue_;

components/viz/service/display_embedder/skia_output_surface_dependency.h

@@ -97,6 +97,8 @@ class VIZ_SERVICE_EXPORT SkiaOutputSurfaceDependency {
   virtual void DidLoseContext(bool offscreen,
                               gpu::error::ContextLostReason reason,
                               const GURL& active_url) = 0;
+
+  virtual base::TimeDelta GetGpuBlockedTimeSinceLastSwap() = 0;
 };
 
 }  // namespace viz

components/viz/service/display_embedder/skia_output_surface_dependency_impl.cc

@@ -26,7 +26,7 @@ SkiaOutputSurfaceDependencyImpl::~SkiaOutputSurfaceDependencyImpl() = default;
 std::unique_ptr<gpu::SingleTaskSequence>
 SkiaOutputSurfaceDependencyImpl::CreateSequence() {
   return std::make_unique<gpu::SchedulerSequence>(
-      gpu_service_impl_->scheduler());
+      gpu_service_impl_->GetGpuScheduler());
 }
 
 bool SkiaOutputSurfaceDependencyImpl::IsUsingVulkan() {
@@ -132,4 +132,9 @@ void SkiaOutputSurfaceDependencyImpl::DidLoseContext(
   gpu_service_impl_->DidLoseContext(offscreen, reason, active_url);
 }
 
+base::TimeDelta
+SkiaOutputSurfaceDependencyImpl::GetGpuBlockedTimeSinceLastSwap() {
+  return gpu_service_impl_->GetGpuScheduler()->TakeTotalBlockingTime();
+}
+
 }  // namespace viz

components/viz/service/display_embedder/skia_output_surface_dependency_impl.h

@@ -55,6 +55,8 @@ class VIZ_SERVICE_EXPORT SkiaOutputSurfaceDependencyImpl
                       gpu::error::ContextLostReason reason,
                       const GURL& active_url) override;
 
+  base::TimeDelta GetGpuBlockedTimeSinceLastSwap() override;
+
  private:
   GpuServiceImpl* const gpu_service_impl_;
   const gpu::SurfaceHandle surface_handle_;

components/viz/service/display_embedder/skia_output_surface_impl_on_gpu.cc

@@ -1446,6 +1446,10 @@ GpuVSyncCallback SkiaOutputSurfaceImplOnGpu::GetGpuVSyncCallback() {
   return gpu_vsync_callback_;
 }
 
+base::TimeDelta SkiaOutputSurfaceImplOnGpu::GetGpuBlockedTimeSinceLastSwap() {
+  return dependency_->GetGpuBlockedTimeSinceLastSwap();
+}
+
 void SkiaOutputSurfaceImplOnGpu::DidSwapBuffersComplete(
     gpu::SwapBuffersCompleteParams params) {
   NOTIMPLEMENTED_LOG_ONCE();

components/viz/service/display_embedder/skia_output_surface_impl_on_gpu.h

@@ -184,6 +184,7 @@ class SkiaOutputSurfaceImplOnGpu : public gpu::ImageTransportSurfaceDelegate,
   void DidSwapBuffersComplete(gpu::SwapBuffersCompleteParams params) override;
   void BufferPresented(const gfx::PresentationFeedback& feedback) override;
   GpuVSyncCallback GetGpuVSyncCallback() override;
+  base::TimeDelta GetGpuBlockedTimeSinceLastSwap() override;
 
   void SendOverlayPromotionNotification(
       base::flat_set<gpu::Mailbox> promotion_denied,

components/viz/service/gl/gpu_service_impl.cc

@@ -935,4 +935,8 @@ void GpuServiceImpl::MaybeExit(bool for_context_loss) {
   std::move(exit_callback_).Run();
 }
 
+gpu::Scheduler* GpuServiceImpl::GetGpuScheduler() {
+  return scheduler_.get();
+}
+
 }  // namespace viz

components/viz/service/gl/gpu_service_impl.h

@@ -196,6 +196,8 @@ class VIZ_SERVICE_EXPORT GpuServiceImpl : public gpu::GpuChannelManagerDelegate,
                          const std::string& shader) override;
   void MaybeExitOnContextLost() override;
   bool IsExiting() const override;
+  gpu::Scheduler* GetGpuScheduler() override;
+
 #if defined(OS_WIN)
   void SendCreatedChildWindow(gpu::SurfaceHandle parent_window,
                               gpu::SurfaceHandle child_window) override;
@@ -235,7 +237,6 @@ class VIZ_SERVICE_EXPORT GpuServiceImpl : public gpu::GpuChannelManagerDelegate,
   gpu::SyncPointManager* sync_point_manager() {
     return gpu_channel_manager_->sync_point_manager();
   }
-  gpu::Scheduler* scheduler() { return scheduler_.get(); }
 
   base::TaskRunner* main_runner() { return main_runner_.get(); }
 

components/viz/service/main/viz_main_impl.cc

@@ -255,7 +255,7 @@ void VizMainImpl::CreateFrameSinkManagerInternal(
   // the same signature. https://crbug.com/928845
   CHECK(!task_executor_);
   task_executor_ = std::make_unique<gpu::GpuInProcessThreadService>(
-      gpu_thread_task_runner_, gpu_service_->scheduler(),
+      gpu_thread_task_runner_, gpu_service_->GetGpuScheduler(),
       gpu_service_->sync_point_manager(), gpu_service_->mailbox_manager(),
       gpu_service_->share_group(), format, gpu_service_->gpu_feature_info(),
       gpu_service_->gpu_channel_manager()->gpu_preferences(),

components/viz/test/test_gpu_service_holder.cc

@@ -206,7 +206,7 @@ void TestGpuServiceHolder::InitializeOnGpuThread(
       /*shutdown_event=*/nullptr);
 
   task_executor_ = std::make_unique<gpu::GpuInProcessThreadService>(
-      gpu_thread_.task_runner(), gpu_service_->scheduler(),
+      gpu_thread_.task_runner(), gpu_service_->GetGpuScheduler(),
       gpu_service_->sync_point_manager(), gpu_service_->mailbox_manager(),
       gpu_service_->share_group(),
       gpu_service_->gpu_channel_manager()

gpu/command_buffer/service/scheduler.cc

@@ -525,7 +525,19 @@ void Scheduler::RunNextTask() {
   {
     base::AutoUnlock auto_unlock(lock_);
     order_data->BeginProcessingOrderNumber(order_num);
+    base::ThreadTicks thread_time_start = base::ThreadTicks::Now();
+    base::TimeTicks wall_time_start = base::TimeTicks::Now();
+
     std::move(closure).Run();
+
+    base::TimeDelta thread_time_elapsed =
+        base::ThreadTicks::Now() - thread_time_start;
+    base::TimeDelta wall_time_elapsed =
+        base::TimeTicks::Now() - wall_time_start;
+    base::TimeDelta blocked_time = wall_time_elapsed - thread_time_elapsed;
+
+    total_blocked_time_ += blocked_time;
+
     if (order_data->IsProcessingOrderNumber())
       order_data->FinishProcessingOrderNumber(order_num);
   }
@@ -546,4 +558,10 @@ void Scheduler::RunNextTask() {
                          base::BindOnce(&Scheduler::RunNextTask, weak_ptr_));
 }
 
+base::TimeDelta Scheduler::TakeTotalBlockingTime() {
+  base::TimeDelta result;
+  std::swap(result, total_blocked_time_);
+  return result;
+}
+
 }  // namespace gpu

gpu/command_buffer/service/scheduler.h

@@ -94,6 +94,9 @@ class GPU_EXPORT Scheduler {
 
   base::WeakPtr<Scheduler> AsWeakPtr();
 
+  // Takes and resets current accumulated blocking time
+  base::TimeDelta TakeTotalBlockingTime();
+
  private:
 
   struct SchedulingState {
@@ -335,6 +338,9 @@ class GPU_EXPORT Scheduler {
   // priority.
   bool rebuild_scheduling_queue_ = false;
 
+  // Accumulated time the thread was blocked during running task
+  base::TimeDelta total_blocked_time_;
+
   base::ThreadChecker thread_checker_;
 
   // Invalidated on main thread.

gpu/ipc/in_process_command_buffer.cc

@@ -1772,6 +1772,11 @@ viz::GpuVSyncCallback InProcessCommandBuffer::GetGpuVSyncCallback() {
                              std::move(handle_gpu_vsync_callback));
 }
 
+base::TimeDelta InProcessCommandBuffer::GetGpuBlockedTimeSinceLastSwap() {
+  return gpu_channel_manager_delegate_->GetGpuScheduler()
+      ->TakeTotalBlockingTime();
+}
+
 void InProcessCommandBuffer::HandleGpuVSyncOnOriginThread(
     base::TimeTicks vsync_time,
     base::TimeDelta vsync_interval) {

gpu/ipc/in_process_command_buffer.h

@@ -178,6 +178,7 @@ class GL_IN_PROCESS_CONTEXT_EXPORT InProcessCommandBuffer
   const GpuPreferences& GetGpuPreferences() const override;
   void BufferPresented(const gfx::PresentationFeedback& feedback) override;
   viz::GpuVSyncCallback GetGpuVSyncCallback() override;
+  base::TimeDelta GetGpuBlockedTimeSinceLastSwap() override;
 
   // Upstream this function to GpuControl if needs arise. Can be called on any
   // thread.

gpu/ipc/service/gles2_command_buffer_stub.cc

@@ -31,6 +31,7 @@
 #include "gpu/command_buffer/service/logger.h"
 #include "gpu/command_buffer/service/mailbox_manager.h"
 #include "gpu/command_buffer/service/memory_tracking.h"
+#include "gpu/command_buffer/service/scheduler.h"
 #include "gpu/command_buffer/service/service_utils.h"
 #include "gpu/command_buffer/service/sync_point_manager.h"
 #include "gpu/command_buffer/service/transfer_buffer_manager.h"
@@ -423,6 +424,10 @@ viz::GpuVSyncCallback GLES2CommandBufferStub::GetGpuVSyncCallback() {
   return viz::GpuVSyncCallback();
 }
 
+base::TimeDelta GLES2CommandBufferStub::GetGpuBlockedTimeSinceLastSwap() {
+  return channel_->scheduler()->TakeTotalBlockingTime();
+}
+
 MemoryTracker* GLES2CommandBufferStub::GetMemoryTracker() const {
   return context_group_->memory_tracker();
 }

gpu/ipc/service/gles2_command_buffer_stub.h

@@ -53,6 +53,7 @@ class GPU_IPC_SERVICE_EXPORT GLES2CommandBufferStub
   const GpuPreferences& GetGpuPreferences() const override;
   void BufferPresented(const gfx::PresentationFeedback& feedback) override;
   viz::GpuVSyncCallback GetGpuVSyncCallback() override;
+  base::TimeDelta GetGpuBlockedTimeSinceLastSwap() override;
 
  private:
   bool HandleMessage(const IPC::Message& message) override;

gpu/ipc/service/gpu_channel_manager_delegate.h

@@ -60,6 +60,9 @@ class GpuChannelManagerDelegate {
   // thread.
   virtual bool IsExiting() const = 0;
 
+  // Returns GPU Scheduler
+  virtual gpu::Scheduler* GetGpuScheduler() = 0;
+
 #if defined(OS_WIN)
   // Tells the delegate that |child_window| was created in the GPU process and
   // to send an IPC to make SetParent() syscall. This syscall is blocked by the

gpu/ipc/service/gpu_channel_test_common.cc

@@ -23,7 +23,7 @@ namespace gpu {
 
 class TestGpuChannelManagerDelegate : public GpuChannelManagerDelegate {
  public:
-  TestGpuChannelManagerDelegate() = default;
+  TestGpuChannelManagerDelegate(Scheduler* scheduler) : scheduler_(scheduler) {}
   ~TestGpuChannelManagerDelegate() override = default;
 
   // GpuChannelManagerDelegate implementation:
@@ -47,8 +47,11 @@ class TestGpuChannelManagerDelegate : public GpuChannelManagerDelegate {
                               SurfaceHandle child_window) override {}
 #endif
 
+  Scheduler* GetGpuScheduler() override { return scheduler_; }
+
  private:
   bool is_exiting_ = false;
+  Scheduler* const scheduler_;
 
   DISALLOW_COPY_AND_ASSIGN(TestGpuChannelManagerDelegate);
 };
@@ -64,7 +67,8 @@ GpuChannelTestCommon::GpuChannelTestCommon(
       sync_point_manager_(new SyncPointManager()),
       shared_image_manager_(new SharedImageManager(false /* thread_safe */)),
       scheduler_(new Scheduler(task_runner_, sync_point_manager_.get())),
-      channel_manager_delegate_(new TestGpuChannelManagerDelegate()) {
+      channel_manager_delegate_(
+          new TestGpuChannelManagerDelegate(scheduler_.get())) {
   // We need GL bindings to actually initialize command buffers.
   if (use_stub_bindings)
     gl::GLSurfaceTestSupport::InitializeOneOffWithStubBindings();

gpu/ipc/service/image_transport_surface_delegate.h

@@ -47,6 +47,9 @@ class GPU_IPC_SERVICE_EXPORT ImageTransportSurfaceDelegate {
   // Callback for GPU vsync signal.  May be called on a different thread.
   virtual viz::GpuVSyncCallback GetGpuVSyncCallback() = 0;
 
+  // Returns how long GpuThread was blocked since last swap. Used for metrics.
+  virtual base::TimeDelta GetGpuBlockedTimeSinceLastSwap() = 0;
+
  protected:
   virtual ~ImageTransportSurfaceDelegate() = default;
 };

gpu/ipc/service/pass_through_image_transport_surface.cc

@@ -9,6 +9,7 @@
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/command_line.h"
+#include "base/metrics/histogram_macros.h"
 #include "build/build_config.h"
 #include "gpu/command_buffer/common/swap_buffers_complete_params.h"
 #include "ui/gfx/vsync_provider.h"
@@ -169,6 +170,29 @@ void PassThroughImageTransportSurface::SetVSyncEnabled(bool enabled) {
   GLSurfaceAdapter::SetVSyncEnabled(enabled);
 }
 
+void PassThroughImageTransportSurface::TrackMultiSurfaceSwap() {
+  // This code is a simple way of enforcing that we only vsync if one surface
+  // is swapping per frame. This provides single window cases a stable refresh
+  // while allowing multi-window cases to not slow down due to multiple syncs
+  // on a single thread. A better way to fix this problem would be to have
+  // each surface present on its own thread.
+  if (g_current_swap_generation_ == swap_generation_) {
+    // No other surface has swapped since we swapped last time.
+    if (g_num_swaps_in_current_swap_generation_ > 1)
+      g_last_multi_window_swap_generation_ = g_current_swap_generation_;
+    g_num_swaps_in_current_swap_generation_ = 0;
+    g_current_swap_generation_++;
+  }
+
+  swap_generation_ = g_current_swap_generation_;
+  g_num_swaps_in_current_swap_generation_++;
+
+  multiple_surfaces_swapped_ =
+      (g_num_swaps_in_current_swap_generation_ > 1) ||
+      (g_current_swap_generation_ - g_last_multi_window_swap_generation_ <
+       kMultiWindowSwapEnableVSyncDelay);
+}
+
 void PassThroughImageTransportSurface::UpdateVSyncEnabled() {
   if (is_gpu_vsync_disabled_) {
     SetVSyncEnabled(false);
@@ -177,33 +201,14 @@ void PassThroughImageTransportSurface::UpdateVSyncEnabled() {
 
   bool should_override_vsync = false;
   if (is_multi_window_swap_vsync_override_enabled_) {
-    // This code is a simple way of enforcing that we only vsync if one surface
-    // is swapping per frame. This provides single window cases a stable refresh
-    // while allowing multi-window cases to not slow down due to multiple syncs
-    // on a single thread. A better way to fix this problem would be to have
-    // each surface present on its own thread.
-
-    if (g_current_swap_generation_ == swap_generation_) {
-      // No other surface has swapped since we swapped last time.
-      if (g_num_swaps_in_current_swap_generation_ > 1)
-        g_last_multi_window_swap_generation_ = g_current_swap_generation_;
-      g_num_swaps_in_current_swap_generation_ = 0;
-      g_current_swap_generation_++;
-    }
-
-    swap_generation_ = g_current_swap_generation_;
-    g_num_swaps_in_current_swap_generation_++;
-
-    should_override_vsync =
-        (g_num_swaps_in_current_swap_generation_ > 1) ||
-        (g_current_swap_generation_ - g_last_multi_window_swap_generation_ <
-         kMultiWindowSwapEnableVSyncDelay);
+    should_override_vsync = multiple_surfaces_swapped_;
   }
   SetVSyncEnabled(!should_override_vsync);
 }
 
 void PassThroughImageTransportSurface::StartSwapBuffers(
     gfx::SwapResponse* response) {
+  TrackMultiSurfaceSwap();
   UpdateVSyncEnabled();
 
 #if DCHECK_IS_ON()
@@ -231,6 +236,28 @@ void PassThroughImageTransportSurface::FinishSwapBuffers(
 #endif
 
   if (delegate_) {
+    auto blocked_time_since_last_swap =
+        delegate_->GetGpuBlockedTimeSinceLastSwap();
+
+    if (!multiple_surfaces_swapped_) {
+      static constexpr base::TimeDelta kTimingMetricsHistogramMin =
+          base::TimeDelta::FromMicroseconds(5);
+      static constexpr base::TimeDelta kTimingMetricsHistogramMax =
+          base::TimeDelta::FromMilliseconds(500);
+      static constexpr uint32_t kTimingMetricsHistogramBuckets = 50;
+
+      base::TimeDelta delta =
+          response.timings.swap_end - response.timings.swap_start;
+      UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+          "GPU.SwapTimeUs", delta, kTimingMetricsHistogramMin,
+          kTimingMetricsHistogramMax, kTimingMetricsHistogramBuckets);
+
+      UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+          "GPU.GpuBlockedBetweenSwapsUs", blocked_time_since_last_swap,
+          kTimingMetricsHistogramMin, kTimingMetricsHistogramMax,
+          kTimingMetricsHistogramBuckets);
+    }
+
     SwapBuffersCompleteParams params;
     params.swap_response = std::move(response);
     delegate_->DidSwapBuffersComplete(std::move(params));

gpu/ipc/service/pass_through_image_transport_surface.h

@@ -55,6 +55,7 @@ class PassThroughImageTransportSurface : public gl::GLSurfaceAdapter {
  private:
   ~PassThroughImageTransportSurface() override;
 
+  void TrackMultiSurfaceSwap();
   void UpdateVSyncEnabled();
 
   void StartSwapBuffers(gfx::SwapResponse* response);
@@ -74,6 +75,7 @@ class PassThroughImageTransportSurface : public gl::GLSurfaceAdapter {
   base::WeakPtr<ImageTransportSurfaceDelegate> delegate_;
   int swap_generation_ = 0;
   bool vsync_enabled_ = true;
+  bool multiple_surfaces_swapped_ = false;
 
   // Local swap ids, which are used to make sure the swap order is correct and
   // the presentation callbacks are not called earlier than the swap ack of the

tools/metrics/histograms/histograms.xml

@@ -52200,6 +52200,19 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="GPU.GpuBlockedBetweenSwapsUs" units="microseconds"
+    expires_after="2020-01-01">
+  <owner>vasilyt@chromium.org</owner>
+  <owner>backer@chromium.org</owner>
+  <summary>
+    This is logged once per frame if the output surface provides timing
+    information. It measures the time Gpu Main thread was blocked (difference
+    between wall time and cpu time) during tasks execution for currect frame.
+    Only reported when there is single surface swap in the same vsync interval.
+    Only reported for platforms supporting high resolution clocks.
+  </summary>
+</histogram>
+
 <histogram name="GPU.GPUChannelHostWaitTime" units="ms"
     expires_after="2019-10-07">
   <obsolete>
@@ -52869,6 +52882,18 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="GPU.SwapTimeUs" units="microseconds"
+    expires_after="2020-01-01">
+  <owner>vasilyt@chromium.org</owner>
+  <owner>backer@chromium.org</owner>
+  <summary>
+    This is logged once per frame if the output surface provides timing
+    information. It measures the time of SwapBuffers call. Only reported when
+    there is single surface swap in the same vsync interval. Only reported for
+    platforms supporting high resolution clocks.
+  </summary>
+</histogram>
+
 <histogram name="GPU.SwiftShaderLifetimeEvents" enum="GPUProcessLifetimeEvent"
     expires_after="2018-06-05">
   <obsolete>