[viz, capture] Add debug logging to FrameSinkVideoCapturer

The logging messages are propagated along the pipeline until they reach
browser process, which already knows how to forward them to the WebRTC
log in a renderer.

Added callback from CaptureOracle to FrameSinkVideoCapturer to forward
log messages.

All the debug logging is behind the chrome feature so it can be enabled
for a fraction of users.

Bug: webrtc:11461
Change-Id: I0005950670e1efb96b86857f1494894e1253f339
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2126986Reviewed-by: Guido Urdaneta <guidou@chromium.org>
Reviewed-by: Dana Fried <dfried@chromium.org>
Reviewed-by: kylechar <kylechar@chromium.org>
Reviewed-by: Andrey Kosyakov <caseq@chromium.org>
Reviewed-by: Martin Barbella <mbarbella@chromium.org>
Reviewed-by: Dmitry Gozman <dgozman@chromium.org>
Commit-Queue: Guido Urdaneta <guidou@chromium.org>
Auto-Submit: Ilya Nikolaevskiy <ilnik@chromium.org>
Cr-Commit-Position: refs/heads/master@{#756223}

chrome/browser/devtools/devtools_eye_dropper.h

@@ -51,6 +51,7 @@ class DevToolsEyeDropper : public content::WebContentsObserver,
       mojo::PendingRemote<viz::mojom::FrameSinkVideoConsumerFrameCallbacks>
           callbacks) override;
   void OnStopped() override;
+  void OnLog(const std::string& /*message*/) override {}
 
   EyeDropperCallback callback_;
   SkBitmap frame_;

chrome/browser/ui/thumbnails/thumbnail_tab_helper.h

@@ -91,6 +91,7 @@ class ThumbnailTabHelper
       mojo::PendingRemote<::viz::mojom::FrameSinkVideoConsumerFrameCallbacks>
           callbacks) override;
   void OnStopped() override;
+  void OnLog(const std::string& /*message*/) override {}
 
   // Returns the dimensions of the multipurpose thumbnail that should be
   // captured from an entire webpage. Can be cropped or compressed later.

components/viz/common/features.cc

@@ -65,6 +65,10 @@ const base::Feature kSplitPartiallyOccludedQuads{
 const base::Feature kUsePreferredIntervalForVideo{
     "UsePreferredIntervalForVideo", base::FEATURE_DISABLED_BY_DEFAULT};
 
+// Whether we should log extra debug information to webrtc native log.
+const base::Feature kWebRtcLogCapturePipeline{
+    "WebRtcLogCapturePipeline", base::FEATURE_DISABLED_BY_DEFAULT};
+
 bool IsVizHitTestingDebugEnabled() {
   return base::CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableVizHitTestDebug);
@@ -137,4 +141,8 @@ bool ShouldSplitPartiallyOccludedQuads() {
   return base::FeatureList::IsEnabled(kSplitPartiallyOccludedQuads);
 }
 
+bool ShouldWebRtcLogCapturePipeline() {
+  return base::FeatureList::IsEnabled(kWebRtcLogCapturePipeline);
+}
+
 }  // namespace features

components/viz/common/features.h

@@ -24,6 +24,7 @@ VIZ_COMMON_EXPORT extern const base::Feature kVizFrameSubmissionForWebView;
 VIZ_COMMON_EXPORT extern const base::Feature kUsePreferredIntervalForVideo;
 VIZ_COMMON_EXPORT extern const base::Feature kUseRealBuffersForPageFlipTest;
 VIZ_COMMON_EXPORT extern const base::Feature kSplitPartiallyOccludedQuads;
+VIZ_COMMON_EXPORT extern const base::Feature kWebRtcLogCapturePipeline;
 
 VIZ_COMMON_EXPORT bool IsVizHitTestingDebugEnabled();
 VIZ_COMMON_EXPORT bool IsUsingSkiaForGLReadback();
@@ -37,6 +38,7 @@ VIZ_COMMON_EXPORT bool IsUsingVizFrameSubmissionForWebView();
 VIZ_COMMON_EXPORT bool IsUsingPreferredIntervalForVideo();
 VIZ_COMMON_EXPORT bool ShouldUseRealBuffersForPageFlipTest();
 VIZ_COMMON_EXPORT bool ShouldSplitPartiallyOccludedQuads();
+VIZ_COMMON_EXPORT bool ShouldWebRtcLogCapturePipeline();
 
 }  // namespace features
 

components/viz/host/client_frame_sink_video_capturer.cc

@@ -157,6 +157,12 @@ void ClientFrameSinkVideoCapturer::OnFrameCaptured(
                              std::move(callbacks));
 }
 
+void ClientFrameSinkVideoCapturer::OnLog(const std::string& message) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+
+  consumer_->OnLog(message);
+}
+
 void ClientFrameSinkVideoCapturer::OnStopped() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
 

components/viz/host/client_frame_sink_video_capturer.h

@@ -123,7 +123,7 @@ class VIZ_HOST_EXPORT ClientFrameSinkVideoCapturer
       mojo::PendingRemote<mojom::FrameSinkVideoConsumerFrameCallbacks>
           callbacks) final;
   void OnStopped() final;
-
+  void OnLog(const std::string& message) final;
   // Establishes connection to FrameSinkVideoCapturer and sends the existing
   // configuration.
   void EstablishConnection();

components/viz/service/frame_sinks/frame_sink_manager_impl.cc

@@ -58,7 +58,8 @@ FrameSinkManagerImpl::FrameSinkManagerImpl(const InitParams& params)
       hit_test_manager_(surface_manager()),
       restart_id_(params.restart_id),
       run_all_compositor_stages_before_draw_(
-          params.run_all_compositor_stages_before_draw) {
+          params.run_all_compositor_stages_before_draw),
+      log_capture_pipeline_in_webrtc_(params.log_capture_pipeline_in_webrtc) {
   surface_manager_.AddObserver(&hit_test_manager_);
   surface_manager_.AddObserver(this);
 }
@@ -273,7 +274,8 @@ void FrameSinkManagerImpl::CreateVideoCapturer(
   video_capturers_.emplace(std::make_unique<FrameSinkVideoCapturerImpl>(
       this, std::move(receiver),
       std::make_unique<media::VideoCaptureOracle>(
-          true /* enable_auto_throttling */)));
+          true /* enable_auto_throttling */),
+      log_capture_pipeline_in_webrtc_));
 }
 
 void FrameSinkManagerImpl::EvictSurfaces(

components/viz/service/frame_sinks/frame_sink_manager_impl.h

@@ -73,6 +73,7 @@ class VIZ_SERVICE_EXPORT FrameSinkManagerImpl
     OutputSurfaceProvider* output_surface_provider = nullptr;
     uint32_t restart_id = BeginFrameSource::kNotRestartableId;
     bool run_all_compositor_stages_before_draw = false;
+    bool log_capture_pipeline_in_webrtc = false;
   };
   explicit FrameSinkManagerImpl(const InitParams& params);
   // TODO(kylechar): Cleanup tests and remove this constructor.
@@ -296,6 +297,9 @@ class VIZ_SERVICE_EXPORT FrameSinkManagerImpl
   // Whether display scheduler should wait for all pipeline stages before draw.
   const bool run_all_compositor_stages_before_draw_;
 
+  // Whether capture pipeline should emit log messages to webrtc log.
+  const bool log_capture_pipeline_in_webrtc_;
+
   // Contains registered frame sink ids, debug labels and synchronization
   // labels. Map entries will be created when frame sink is registered and
   // destroyed when frame sink is invalidated.

components/viz/service/frame_sinks/video_capture/frame_sink_video_capturer_impl.cc

@@ -10,6 +10,7 @@
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
+#include "base/callback.h"
 #include "base/memory/read_only_shared_memory_region.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/stl_util.h"
@@ -63,16 +64,21 @@ constexpr gfx::ColorSpace FrameSinkVideoCapturerImpl::kDefaultColorSpace;
 FrameSinkVideoCapturerImpl::FrameSinkVideoCapturerImpl(
     FrameSinkVideoCapturerManager* frame_sink_manager,
     mojo::PendingReceiver<mojom::FrameSinkVideoCapturer> receiver,
-    std::unique_ptr<media::VideoCaptureOracle> oracle)
+    std::unique_ptr<media::VideoCaptureOracle> oracle,
+    bool log_to_webrtc)
     : frame_sink_manager_(frame_sink_manager),
       copy_request_source_(base::UnguessableToken::Create()),
       clock_(base::DefaultTickClock::GetInstance()),
       oracle_(std::move(oracle)),
       frame_pool_(kDesignLimitMaxFrames),
-      feedback_weak_factory_(oracle_.get()) {
+      feedback_weak_factory_(oracle_.get()),
+      log_to_webrtc_(log_to_webrtc) {
   DCHECK(frame_sink_manager_);
   DCHECK(oracle_);
-
+  if (log_to_webrtc_) {
+    oracle_->SetLogCallback(base::BindRepeating(
+        &FrameSinkVideoCapturerImpl::OnLog, base::Unretained(this)));
+  }
   // Instantiate a default base::OneShotTimer instance.
   refresh_frame_retry_timer_.emplace();
 
@@ -337,6 +343,11 @@ void FrameSinkVideoCapturerImpl::RefreshSoon() {
   if (source_size != oracle_->source_size()) {
     oracle_->SetSourceSize(source_size);
     InvalidateEntireSource();
+    if (log_to_webrtc_) {
+      consumer_->OnLog(
+          base::StringPrintf("VFC: RefreshSoon() changed active frame size: %s",
+                             source_size.ToString().c_str()));
+    }
   }
 
   MaybeCaptureFrame(VideoCaptureOracle::kRefreshRequest, gfx::Rect(),
@@ -360,6 +371,11 @@ void FrameSinkVideoCapturerImpl::OnFrameDamaged(
   } else {
     oracle_->SetSourceSize(frame_size);
     InvalidateEntireSource();
+    if (log_to_webrtc_ && consumer_) {
+      consumer_->OnLog(
+          base::StringPrintf("VFC: OnFramedamaged() changed frame size: %s",
+                             frame_size.ToString().c_str()));
+    }
   }
 
   MaybeCaptureFrame(VideoCaptureOracle::kCompositorUpdate, damage_rect,
@@ -583,6 +599,30 @@ void FrameSinkVideoCapturerImpl::MaybeCaptureFrame(
   // If the frame is a resurrected one, just deliver it since it already
   // contains the most up-to-date capture of the source content.
   if (can_resurrect_content) {
+    if (log_to_webrtc_) {
+      std::string strides = "";
+      switch (frame->format()) {
+        case media::PIXEL_FORMAT_I420:
+          strides = base::StringPrintf("strideY:%d StrideU:%d StrideV:%d",
+                                       frame->stride(VideoFrame::kYPlane),
+                                       frame->stride(VideoFrame::kUPlane),
+                                       frame->stride(VideoFrame::kVPlane));
+          break;
+        case media::PIXEL_FORMAT_ARGB:
+          strides = base::StringPrintf("strideRGBA:%d",
+                                       frame->stride(VideoFrame::kARGBPlane));
+          break;
+        default:
+          strides = "strides:???";
+      }
+      consumer_->OnLog(base::StringPrintf(
+          "VFC: Ressurecting frame format=%s frame_coded_size: %s "
+          "frame_visible_rect: %s frame_natural_size: %s %s",
+          VideoPixelFormatToString(frame->format()).c_str(),
+          frame->coded_size().ToString().c_str(),
+          frame->visible_rect().ToString().c_str(),
+          frame->natural_size().ToString().c_str(), strides.c_str()));
+    }
     OnFrameReadyForDelivery(capture_frame_number, oracle_frame_number,
                             content_rect, std::move(frame));
     return;
@@ -613,6 +653,20 @@ void FrameSinkVideoCapturerImpl::MaybeCaptureFrame(
   // being captured.
   dirty_rect_ = gfx::Rect();
 
+  if (log_to_webrtc_) {
+    std::string format =
+        pixel_format_ == media::PIXEL_FORMAT_I420 ? "I420" : "RGBA_bitmap";
+    consumer_->OnLog(base::StringPrintf(
+        "VFC: Sending CopyRequest: "
+        "format=%s area:%s "
+        "scale_from: %s "
+        "scale_to: %s "
+        "frame pool utilization: %f",
+        format.c_str(), request->area().ToString().c_str(),
+        request->scale_from().ToString().c_str(),
+        request->scale_to().ToString().c_str(), utilization));
+  }
+
   resolved_target_->RequestCopyOfOutput(LocalSurfaceId(), std::move(request));
 }
 
@@ -630,6 +684,38 @@ void FrameSinkVideoCapturerImpl::DidCopyFrame(
   DCHECK(frame);
   DCHECK(result);
 
+  if (log_to_webrtc_ && consumer_) {
+    std::string format = "";
+    std::string strides = "";
+    switch (result->format()) {
+      case CopyOutputResult::Format::I420_PLANES:
+        format = "I420";
+        strides = base::StringPrintf("strideY:%d StrideU:%d StrideV:%d",
+                                     frame->stride(VideoFrame::kYPlane),
+                                     frame->stride(VideoFrame::kUPlane),
+                                     frame->stride(VideoFrame::kVPlane));
+        break;
+      case CopyOutputResult::Format::RGBA_BITMAP:
+        format = "RGBA_Bitmap";
+        strides = base::StringPrintf("strideRGBA:%d",
+                                     frame->stride(VideoFrame::kARGBPlane));
+        break;
+      case CopyOutputResult::Format::RGBA_TEXTURE:
+        format = "RGBA_Texture";
+        strides = base::StringPrintf("strideRGBA:%d",
+                                     frame->stride(VideoFrame::kARGBPlane));
+        break;
+    }
+    consumer_->OnLog(base::StringPrintf(
+        "VFC: got CopyOutputResult: format=%s size:%s frame_coded_size: %s "
+        "frame_visible_rect: %s frame_natural_size: %s content_rect: %s %s",
+        format.c_str(), result->size().ToString().c_str(),
+        frame->coded_size().ToString().c_str(),
+        frame->visible_rect().ToString().c_str(),
+        frame->natural_size().ToString().c_str(),
+        content_rect.ToString().c_str(), strides.c_str()));
+  }
+
   // Stop() should have canceled any outstanding copy requests. So, by reaching
   // this point, |consumer_| should be bound.
   DCHECK(consumer_);
@@ -840,6 +926,12 @@ gfx::Rect FrameSinkVideoCapturerImpl::ExpandRectToI420SubsampleBoundaries(
   return gfx::Rect(x, y, r - x, b - y);
 }
 
+void FrameSinkVideoCapturerImpl::OnLog(const std::string& message) {
+  if (log_to_webrtc_ && consumer_) {
+    consumer_->OnLog(message);
+  }
+}
+
 FrameSinkVideoCapturerImpl::CapturedFrame::CapturedFrame(
     int64_t capture_frame_number,
     OracleFrameNumber oracle_frame_number,

components/viz/service/frame_sinks/video_capture/frame_sink_video_capturer_impl.h

@@ -10,7 +10,7 @@
 #include <memory>
 #include <queue>
 #include <vector>
-
+#include "base/callback_forward.h"
 #include "base/containers/flat_map.h"
 #include "base/macros.h"
 #include "base/memory/weak_ptr.h"
@@ -79,7 +79,8 @@ class VIZ_SERVICE_EXPORT FrameSinkVideoCapturerImpl final
   FrameSinkVideoCapturerImpl(
       FrameSinkVideoCapturerManager* frame_sink_manager,
       mojo::PendingReceiver<mojom::FrameSinkVideoCapturer> receiver,
-      std::unique_ptr<media::VideoCaptureOracle> oracle);
+      std::unique_ptr<media::VideoCaptureOracle> oracle,
+      bool log_to_webrtc);
 
   ~FrameSinkVideoCapturerImpl() final;
 
@@ -227,6 +228,8 @@ class VIZ_SERVICE_EXPORT FrameSinkVideoCapturerImpl final
   // numbers.
   static gfx::Rect ExpandRectToI420SubsampleBoundaries(const gfx::Rect& rect);
 
+  void OnLog(const std::string& message);
+
   // Owner/Manager of this instance.
   FrameSinkVideoCapturerManager* const frame_sink_manager_;
 
@@ -335,6 +338,9 @@ class VIZ_SERVICE_EXPORT FrameSinkVideoCapturerImpl final
   // in-flight frame deliveries.
   base::WeakPtrFactory<media::VideoCaptureOracle> feedback_weak_factory_;
 
+  // Enables debug log messages to be sent to webrtc native log.
+  const bool log_to_webrtc_;
+
   // A weak pointer factory used for cancelling the results from any in-flight
   // copy output requests.
   base::WeakPtrFactory<FrameSinkVideoCapturerImpl> capture_weak_factory_{this};

components/viz/service/frame_sinks/video_capture/frame_sink_video_capturer_impl_unittest.cc

@@ -124,6 +124,7 @@ class MockConsumer : public mojom::FrameSinkVideoConsumer {
 
   MOCK_METHOD0(OnFrameCapturedMock, void());
   MOCK_METHOD0(OnStopped, void());
+  MOCK_METHOD1(OnLog, void(const std::string&));
 
   int num_frames_received() const { return frames_.size(); }
 
@@ -379,7 +380,7 @@ class FrameSinkVideoCapturerTest : public testing::Test {
         true /* enable_auto_throttling */);
     oracle_ = oracle.get();
     capturer_ = std::make_unique<FrameSinkVideoCapturerImpl>(
-        &frame_sink_manager_, mojo::NullReceiver(), std::move(oracle));
+        &frame_sink_manager_, mojo::NullReceiver(), std::move(oracle), false);
   }
 
   void SetUp() override {

components/viz/service/main/viz_compositor_thread_runner_impl.cc

@@ -198,6 +198,8 @@ void VizCompositorThreadRunnerImpl::CreateFrameSinkManagerOnCompositorThread(
   init_params.restart_id = params->restart_id;
   init_params.run_all_compositor_stages_before_draw =
       run_all_compositor_stages_before_draw;
+  init_params.log_capture_pipeline_in_webrtc =
+      features::ShouldWebRtcLogCapturePipeline();
 
   frame_sink_manager_ = std::make_unique<FrameSinkManagerImpl>(init_params);
   frame_sink_manager_->BindAndSetClient(

content/browser/devtools/devtools_video_consumer.h

@@ -70,6 +70,7 @@ class CONTENT_EXPORT DevToolsVideoConsumer
       mojo::PendingRemote<viz::mojom::FrameSinkVideoConsumerFrameCallbacks>
           callbacks) override;
   void OnStopped() override;
+  void OnLog(const std::string& /*message*/) override {}
 
   // Default min frame size is 1x1, as otherwise, nothing would be captured.
   static constexpr gfx::Size kDefaultMinFrameSize = gfx::Size(1, 1);

content/browser/media/capture/frame_sink_video_capture_device.cc

@@ -263,6 +263,21 @@ void FrameSinkVideoCaptureDevice::OnStopped() {
   OnFatalError("Capturer service cannot continue.");
 }
 
+void FrameSinkVideoCaptureDevice::OnLog(const std::string& message) {
+  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+
+  if (receiver_) {
+    if (BrowserThread::CurrentlyOn(BrowserThread::IO)) {
+      receiver_->OnLog(message);
+    } else {
+      base::PostTask(
+          FROM_HERE, {BrowserThread::IO},
+          base::BindOnce(&media::VideoFrameReceiver::OnLog,
+                         base::Unretained(receiver_.get()), message));
+    }
+  }
+}
+
 void FrameSinkVideoCaptureDevice::OnTargetChanged(
     const viz::FrameSinkId& frame_sink_id) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);

content/browser/media/capture/frame_sink_video_capture_device.h

@@ -82,6 +82,7 @@ class CONTENT_EXPORT FrameSinkVideoCaptureDevice
       mojo::PendingRemote<viz::mojom::FrameSinkVideoConsumerFrameCallbacks>
           callbacks) final;
   void OnStopped() final;
+  void OnLog(const std::string& message) final;
 
   // These are called to notify when the capture target has changed or was
   // permanently lost.

media/capture/content/video_capture_oracle.cc

@@ -6,6 +6,7 @@
 
 #include <algorithm>
 
+#include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/format_macros.h"
 #include "base/numerics/safe_conversions.h"
@@ -412,6 +413,15 @@ void VideoCaptureOracle::AnalyzeAndAdjust(const base::TimeTicks analyze_time) {
   const int decreased_area = AnalyzeForDecreasedArea(analyze_time);
   if (decreased_area > 0) {
     resolution_chooser_.SetTargetFrameArea(decreased_area);
+    if (!emit_log_message_cb_.is_null()) {
+      emit_log_message_cb_.Run(base::StringPrintf(
+          "VFC: CaptureOracle - Decreasing resolution. "
+          "buffer_utilization_: %lf "
+          "estimated_cappable_area: %lf "
+          "capture_size: %s ",
+          buffer_pool_utilization_.current(), estimated_capable_area_.current(),
+          capture_size_.ToString().c_str()));
+    }
     return;
   }
 
@@ -587,4 +597,9 @@ bool VideoCaptureOracle::HasSufficientRecentFeedback(
          (now - accumulator.update_time() <= kMaxTimeSinceLastFeedbackUpdate);
 }
 
+void VideoCaptureOracle::SetLogCallback(
+    base::RepeatingCallback<void(const std::string&)> emit_log_cb) {
+  emit_log_message_cb_ = std::move(emit_log_cb);
+}
+
 }  // namespace media

media/capture/content/video_capture_oracle.h

@@ -5,7 +5,7 @@
 #ifndef MEDIA_CAPTURE_CONTENT_VIDEO_CAPTURE_ORACLE_H_
 #define MEDIA_CAPTURE_CONTENT_VIDEO_CAPTURE_ORACLE_H_
 
-#include "base/callback_forward.h"
+#include "base/callback.h"
 #include "base/time/time.h"
 #include "media/base/feedback_signal_accumulator.h"
 #include "media/capture/capture_export.h"
@@ -139,6 +139,11 @@ class CAPTURE_EXPORT VideoCaptureOracle {
   static constexpr base::TimeDelta kDefaultMinSizeChangePeriod =
       base::TimeDelta::FromSeconds(3);
 
+  void SetLogCallback(
+      base::RepeatingCallback<void(const std::string&)> emit_log_cb);
+
+  void Log(const std::string& message);
+
  private:
   // Retrieve/Assign a frame timestamp by capture |frame_number|.  Only valid
   // when IsFrameInRecentHistory(frame_number) returns true.
@@ -253,6 +258,10 @@ class CAPTURE_EXPORT VideoCaptureOracle {
   // animation.  This determines whether capture size increases will be
   // aggressive (because content is not animating).
   base::TimeTicks last_time_animation_was_detected_;
+
+  // Callback for webrtc native log. It should check for corresponding feature
+  // inside.
+  base::RepeatingCallback<void(const std::string&)> emit_log_message_cb_;
 };
 
 }  // namespace media

services/viz/privileged/mojom/compositing/frame_sink_video_capture.mojom

@@ -52,6 +52,9 @@ interface FrameSinkVideoConsumer {
   // Indicates that OnFrameCaptured() will not be called again, an end-of-stream
   // signal.
   OnStopped();
+  // Called to deliver a log message to the consumer.
+  // Currently used to populate WebRTC native logs.
+  OnLog(string message);
 };
 
 // Interface to an implementation that captures the frames of a