[Chromecast] Add logging for overlay/hole frames

This is to help investigate bugs where audio can be heard but
video is not seen.  There can be other causes for this, but
hole punching failure is the most likely one, and our logs currently
give no insight into what's going on with the overlay frames.

BUG=internal b/26603504

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

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

chromecast/renderer/media/hole_frame_factory.cc

@@ -57,9 +57,12 @@ scoped_refptr<::media::VideoFrame> HoleFrameFactory::CreateHoleFrame(
   // No texture => audio device.  size empty => video has one dimension = 0.
   // Dimension 0 case triggers a DCHECK later on in TextureMailbox if we push
   // through the overlay path.
-  if (!texture_ || size.IsEmpty())
+  if (!texture_ || size.IsEmpty()) {
+    LOG(INFO) << "Create black frame " << size.width() << "x" << size.height();
     return ::media::VideoFrame::CreateBlackFrame(gfx::Size(1, 1));
+  }
 
+  LOG(INFO) << "Create hole frame " << size.width() << "x" << size.height();
   scoped_refptr<::media::VideoFrame> frame =
       ::media::VideoFrame::WrapNativeTexture(
           ::media::PIXEL_FORMAT_XRGB,

ui/ozone/platform/cast/surface_factory_cast.cc

@@ -78,7 +78,9 @@ SurfaceFactoryCast::SurfaceFactoryCast(scoped_ptr<CastEglPlatform> egl_platform)
       window_(0),
       display_size_(GetInitialDisplaySize()),
       new_display_size_(GetInitialDisplaySize()),
-      egl_platform_(std::move(egl_platform)) {}
+      egl_platform_(std::move(egl_platform)),
+      overlay_count_(0),
+      previous_frame_overlay_count_(0) {}
 
 SurfaceFactoryCast::~SurfaceFactoryCast() {
   ShutdownHardware();
@@ -128,6 +130,31 @@ void SurfaceFactoryCast::ShutdownHardware() {
   state_ = kUninitialized;
 }
 
+void SurfaceFactoryCast::OnSwapBuffers() {
+  DCHECK(overlay_count_ == 0 || overlay_count_ == 1);
+
+  // Logging for overlays to help diagnose bugs when nothing is visible on
+  // screen.  Logging this every frame would be overwhelming, so we just
+  // log on the transitions from 0 overlays -> 1 overlay and vice versa.
+  if (overlay_count_ == 0 && previous_frame_overlay_count_ != 0) {
+    LOG(INFO) << "Overlays deactivated";
+  } else if (overlay_count_ != 0 && previous_frame_overlay_count_ == 0) {
+    LOG(INFO) << "Overlays activated: " << overlay_bounds_.ToString();
+  } else if (overlay_count_ == previous_frame_overlay_count_ &&
+             overlay_bounds_ != previous_frame_overlay_bounds_) {
+    LOG(INFO) << "Overlay geometry changed to " << overlay_bounds_.ToString();
+  }
+
+  previous_frame_overlay_count_ = overlay_count_;
+  previous_frame_overlay_bounds_ = overlay_bounds_;
+  overlay_count_ = 0;
+}
+
+void SurfaceFactoryCast::OnOverlayScheduled(const gfx::Rect& display_bounds) {
+  ++overlay_count_;
+  overlay_bounds_ = display_bounds;
+}
+
 scoped_ptr<SurfaceOzoneCanvas> SurfaceFactoryCast::CreateCanvasForWidget(
     gfx::AcceleratedWidget widget) {
   // Software canvas support only in headless mode
@@ -222,7 +249,7 @@ scoped_refptr<NativePixmap> SurfaceFactoryCast::CreateNativePixmap(
     gfx::BufferUsage usage) {
   class CastPixmap : public NativePixmap {
    public:
-    CastPixmap() {}
+    CastPixmap(SurfaceFactoryCast* parent) : parent_(parent) {}
 
     void* GetEGLClientBuffer() const override {
       // TODO(halliwell): try to implement this through CastEglPlatform.
@@ -240,6 +267,7 @@ scoped_refptr<NativePixmap> SurfaceFactoryCast::CreateNativePixmap(
                               gfx::OverlayTransform plane_transform,
                               const gfx::Rect& display_bounds,
                               const gfx::RectF& crop_rect) override {
+      parent_->OnOverlayScheduled(display_bounds);
       return true;
     }
     void SetProcessingCallback(
@@ -251,9 +279,11 @@ scoped_refptr<NativePixmap> SurfaceFactoryCast::CreateNativePixmap(
    private:
     ~CastPixmap() override {}
 
+    SurfaceFactoryCast* parent_;
+
     DISALLOW_COPY_AND_ASSIGN(CastPixmap);
   };
-  return make_scoped_refptr(new CastPixmap);
+  return make_scoped_refptr(new CastPixmap(this));
 }
 
 bool SurfaceFactoryCast::LoadEGLGLES2Bindings(

ui/ozone/platform/cast/surface_factory_cast.h

@@ -9,6 +9,7 @@
 
 #include "base/macros.h"
 #include "base/memory/scoped_ptr.h"
+#include "ui/gfx/geometry/rect.h"
 #include "ui/gfx/geometry/size.h"
 #include "ui/ozone/public/surface_factory_ozone.h"
 
@@ -48,6 +49,10 @@ class SurfaceFactoryCast : public SurfaceFactoryOzone {
   void TerminateDisplay();
   void ShutdownHardware();
 
+  // API for keeping track of overlays per frame for logging purposes
+  void OnSwapBuffers();
+  void OnOverlayScheduled(const gfx::Rect& display_bounds);
+
  private:
   enum HardwareState { kUninitialized, kInitialized, kFailed };
 
@@ -64,6 +69,12 @@ class SurfaceFactoryCast : public SurfaceFactoryOzone {
   gfx::Size new_display_size_;
   scoped_ptr<chromecast::CastEglPlatform> egl_platform_;
 
+  // Overlays scheduled in current and previous frames:
+  int overlay_count_;
+  gfx::Rect overlay_bounds_;
+  int previous_frame_overlay_count_;
+  gfx::Rect previous_frame_overlay_bounds_;
+
   DISALLOW_COPY_AND_ASSIGN(SurfaceFactoryCast);
 };
 

ui/ozone/platform/cast/surface_ozone_egl_cast.cc

@@ -18,11 +18,13 @@ intptr_t SurfaceOzoneEglCast::GetNativeWindow() {
 }
 
 bool SurfaceOzoneEglCast::OnSwapBuffers() {
+  parent_->OnSwapBuffers();
   return true;
 }
 
 void SurfaceOzoneEglCast::OnSwapBuffersAsync(
     const SwapCompletionCallback& callback) {
+  parent_->OnSwapBuffers();
   callback.Run(gfx::SwapResult::SWAP_ACK);
 }