Enable video stats reporting when using WebRTC

remoting/protocol/webrtc_video_stream.cc

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "remoting/protocol/webrtc_video_stream.h"
 
 #include "base/logging.h"
 #include "base/single_thread_task_runner.h"
 #include "base/task_runner_util.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "remoting/base/constants.h"
 #include "remoting/proto/video.pb.h"
+#include "remoting/protocol/frame_stats.h"
+#include "remoting/protocol/host_video_stats_dispatcher.h"
 #include "remoting/protocol/webrtc_dummy_video_capturer.h"
 #include "remoting/protocol/webrtc_transport.h"
 #include "third_party/webrtc/api/mediastreaminterface.h"
 #include "third_party/webrtc/api/peerconnectioninterface.h"
 #include "third_party/webrtc/api/test/fakeconstraints.h"
 #include "third_party/webrtc/media/base/videocapturer.h"
 
 namespace remoting {
 namespace protocol {
 
 namespace {
 
-// Task running on the encoder thread to encode the |frame|.
-std::unique_ptr<VideoPacket> EncodeFrame(
-    VideoEncoder* encoder,
-    std::unique_ptr<webrtc::DesktopFrame> frame,
-    uint32_t target_bitrate_kbps,
-    bool key_frame_request,
-    int64_t capture_time_ms) {
-  uint32_t flags = 0;
-  if (key_frame_request)
-    flags |= VideoEncoder::REQUEST_KEY_FRAME;
-
-  base::TimeTicks current = base::TimeTicks::Now();
-  encoder->UpdateTargetBitrate(target_bitrate_kbps);
-  std::unique_ptr<VideoPacket> packet = encoder->Encode(*frame, flags);
-  if (!packet)
-    return nullptr;
-  // TODO(isheriff): Note that while VideoPacket capture time is supposed
-  // to be capture duration, we (ab)use it for capture timestamp here. This
-  // will go away when we move away from VideoPacket.
-  packet->set_capture_time_ms(capture_time_ms);
-
-  VLOG(1) << "Encode duration "
-          << (base::TimeTicks::Now() - current).InMilliseconds()
-          << " payload size " << packet->data().size();
-  return packet;
-}
-
 void PostTaskOnTaskRunner(
     scoped_refptr<base::SingleThreadTaskRunner> task_runner,
     const base::Closure& task) {
   task_runner->PostTask(FROM_HERE, task);
 }
 
 template <typename ParamType>
 void PostTaskOnTaskRunnerWithParam(
     scoped_refptr<base::SingleThreadTaskRunner> task_runner,
     const base::Callback<void(ParamType param)>& task,
     ParamType param) {
   task_runner->PostTask(FROM_HERE, base::Bind(task, param));
 }
 
 }  // namespace
 
 const char kStreamLabel[] = "screen_stream";
 const char kVideoLabel[] = "screen_video";
 
+struct WebrtcVideoStream::FrameTimestamps {
+  // The following two fields are set only for one frame after each incoming
+  // input event. |input_event_client_timestamp| is event timestamp
+  // received from the client. |input_event_received_time| is local time when
+  // the event was received.
+  int64_t input_event_client_timestamp = -1;
+  base::TimeTicks input_event_received_time;
+
+  base::TimeTicks capture_started_time;
+  base::TimeTicks capture_ended_time;
+  base::TimeDelta capture_delay;
+  base::TimeTicks encode_started_time;
+  base::TimeTicks encode_ended_time;
+  base::TimeTicks can_send_time;

[Irfan, 2016/08/09 17:00:37]

what is this for ?

[Sergey Ulanov, 2016/08/10 18:07:44]

It wasn't used, removed now.

+};
+
+struct WebrtcVideoStream::PacketWithTimestamps {
+  std::unique_ptr<VideoPacket> packet;
+  std::unique_ptr<FrameTimestamps> timestamps;

[Irfan, 2016/08/09 17:00:37]

It would be nice to have a consistency on the naming of Packet and Frame here.
They both refer to the same thing. Is it time to call VideoPacket VideoFrame ?

[Sergey Ulanov, 2016/08/10 18:07:45]

packet = encoded frame
Calling it VideoFrame would make it confusing as we also have
webrtc::DesktopFrame, which is used for decoded frames.
But I agree that this distinction between video packet and frame is not clear. I
could rename VideoPacket to EncodedVideoFrame, WDYT?

+};
+
 WebrtcVideoStream::WebrtcVideoStream()
-    : main_task_runner_(base::ThreadTaskRunnerHandle::Get()),
-      weak_factory_(this) {}
+    : video_stats_dispatcher_(kStreamLabel), weak_factory_(this) {}
 
 WebrtcVideoStream::~WebrtcVideoStream() {
   if (stream_) {
     for (const auto& track : stream_->GetVideoTracks()) {
       track->GetSource()->Stop();
       stream_->RemoveTrack(track.get());
     }
     peer_connection_->RemoveStream(stream_.get());
   }
   encode_task_runner_->DeleteSoon(FROM_HERE, encoder_.release());
@@ skipping 13 matching lines @@
   scoped_refptr<webrtc::PeerConnectionFactoryInterface> peer_connection_factory(
       webrtc_transport->peer_connection_factory());
   peer_connection_ = webrtc_transport->peer_connection();
   DCHECK(peer_connection_factory);
   DCHECK(peer_connection_);
 
   encode_task_runner_ = encode_task_runner;
   capturer_ = std::move(desktop_capturer);
   webrtc_transport_ = webrtc_transport;
   encoder_ = std::move(video_encoder);
-  capture_timer_.reset(new base::RepeatingTimer());
-
   capturer_->Start(this);
 
   // Set video stream constraints.
   webrtc::FakeConstraints video_constraints;
   video_constraints.AddMandatory(
       webrtc::MediaConstraintsInterface::kMinFrameRate, 5);
 
   rtc::scoped_refptr<webrtc::VideoTrackSourceInterface> src =
       peer_connection_factory->CreateVideoSource(new WebrtcDummyVideoCapturer(),
                                                  &video_constraints);
   rtc::scoped_refptr<webrtc::VideoTrackInterface> video_track =
       peer_connection_factory->CreateVideoTrack(kVideoLabel, src);
 
   stream_ = peer_connection_factory->CreateLocalMediaStream(kStreamLabel);
 
   if (!stream_->AddTrack(video_track.get()) ||
       !peer_connection_->AddStream(stream_.get())) {
     stream_ = nullptr;
     peer_connection_ = nullptr;
     return false;
   }
 
   // Register for PLI requests.
   webrtc_transport_->video_encoder_factory()->SetKeyFrameRequestCallback(
-      base::Bind(&PostTaskOnTaskRunner, main_task_runner_,
+      base::Bind(&PostTaskOnTaskRunner, base::ThreadTaskRunnerHandle::Get(),
                  base::Bind(&WebrtcVideoStream::SetKeyFrameRequest,
                             weak_factory_.GetWeakPtr())));
 
   // Register for target bitrate notifications.
   webrtc_transport_->video_encoder_factory()->SetTargetBitrateCallback(
-      base::Bind(&PostTaskOnTaskRunnerWithParam<int>, main_task_runner_,
+      base::Bind(&PostTaskOnTaskRunnerWithParam<int>,
+                 base::ThreadTaskRunnerHandle::Get(),
                  base::Bind(&WebrtcVideoStream::SetTargetBitrate,
                             weak_factory_.GetWeakPtr())));
 
+  video_stats_dispatcher_.Init(webrtc_transport_->CreateOutgoingChannel(
+                                   video_stats_dispatcher_.channel_name()),
+                               this);
   return true;
 }
 
 void WebrtcVideoStream::Pause(bool pause) {
   DCHECK(thread_checker_.CalledOnValidThread());
   if (pause) {
-    capture_timer_->Stop();
+    capture_timer_.Stop();
   } else {
     if (received_first_frame_request_) {
       StartCaptureTimer();
     }
   }
 }
 
 void WebrtcVideoStream::OnInputEventReceived(int64_t event_timestamp) {
-  NOTIMPLEMENTED();
+  DCHECK(thread_checker_.CalledOnValidThread());
+
+  if (!next_frame_timestamps_)
+    next_frame_timestamps_.reset(new FrameTimestamps());
+  next_frame_timestamps_->input_event_client_timestamp = event_timestamp;
+  next_frame_timestamps_->input_event_received_time = base::TimeTicks::Now();
 }
 
 void WebrtcVideoStream::SetLosslessEncode(bool want_lossless) {
   NOTIMPLEMENTED();
 }
 
 void WebrtcVideoStream::SetLosslessColor(bool want_lossless) {
   NOTIMPLEMENTED();
 }
 
 void WebrtcVideoStream::SetObserver(Observer* observer) {
   DCHECK(thread_checker_.CalledOnValidThread());
   observer_ = observer;
 }
 
 void WebrtcVideoStream::SetKeyFrameRequest() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   key_frame_request_ = true;
   if (!received_first_frame_request_) {
     received_first_frame_request_ = true;
     StartCaptureTimer();
-    main_task_runner_->PostTask(
+    base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(&WebrtcVideoStream::StartCaptureTimer,
                               weak_factory_.GetWeakPtr()));
   }
 }
 
 void WebrtcVideoStream::StartCaptureTimer() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  capture_timer_->Start(FROM_HERE, base::TimeDelta::FromSeconds(1) / 30, this,
-                        &WebrtcVideoStream::CaptureNextFrame);
+  capture_timer_.Start(FROM_HERE, base::TimeDelta::FromSeconds(1) / 30, this,
+                       &WebrtcVideoStream::CaptureNextFrame);
 }
 
 void WebrtcVideoStream::SetTargetBitrate(int target_bitrate_kbps) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   VLOG(1) << "Set Target bitrate " << target_bitrate_kbps;
   target_bitrate_kbps_ = target_bitrate_kbps;
 }
 
 bool WebrtcVideoStream::ClearAndGetKeyFrameRequest() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   bool key_frame_request = key_frame_request_;
   key_frame_request_ = false;
   return key_frame_request;
 }
 
 void WebrtcVideoStream::OnCaptureResult(
     webrtc::DesktopCapturer::Result result,
     std::unique_ptr<webrtc::DesktopFrame> frame) {
   DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(capture_pending_);
+  capture_pending_ = false;
 
-  base::TimeTicks captured_ticks = base::TimeTicks::Now();
-  int64_t capture_timestamp_ms =
-      (captured_ticks - base::TimeTicks()).InMilliseconds();
-  capture_pending_ = false;
 
   if (encode_pending_) {
     // TODO(isheriff): consider queuing here
     VLOG(1) << "Dropping captured frame since encoder is still busy";
     return;
   }
 
   // TODO(sergeyu): Handle ERROR_PERMANENT result here.
 
   webrtc::DesktopVector dpi =
       frame->dpi().is_zero() ? webrtc::DesktopVector(kDefaultDpi, kDefaultDpi)
                              : frame->dpi();
 
   if (!frame_size_.equals(frame->size()) || !frame_dpi_.equals(dpi)) {
     frame_size_ = frame->size();
     frame_dpi_ = dpi;
     if (observer_)
       observer_->OnVideoSizeChanged(this, frame_size_, frame_dpi_);
   }
+
+  captured_frame_timestamps_->capture_ended_time = base::TimeTicks::Now();
+  captured_frame_timestamps_->capture_delay =
+      base::TimeDelta::FromMilliseconds(frame->capture_time_ms());
+
   encode_pending_ = true;
   base::PostTaskAndReplyWithResult(
       encode_task_runner_.get(), FROM_HERE,
-      base::Bind(&EncodeFrame, encoder_.get(), base::Passed(std::move(frame)),
-                 target_bitrate_kbps_, ClearAndGetKeyFrameRequest(),
-                 capture_timestamp_ms),
+      base::Bind(&WebrtcVideoStream::EncodeFrame, encoder_.get(),
+                 base::Passed(std::move(frame)),
+                 base::Passed(std::move(captured_frame_timestamps_)),
+                 target_bitrate_kbps_, ClearAndGetKeyFrameRequest()),
       base::Bind(&WebrtcVideoStream::OnFrameEncoded,
                  weak_factory_.GetWeakPtr()));
 }
 
+void WebrtcVideoStream::OnChannelInitialized(
+    ChannelDispatcherBase* channel_dispatcher) {
+  DCHECK(&video_stats_dispatcher_ == channel_dispatcher);

[Irfan, 2016/08/09 17:00:37]

Are these callbacks helpful ? It sounds like we always check if the the channel
is connected

[Sergey Ulanov, 2016/08/10 18:07:45]

OnChannelClosed() is useful if only to log the warning. ChannelDispatcherBase
expects some callback and OnChannelInitialized() is useful for other channels.

+}
+void WebrtcVideoStream::OnChannelClosed(
+    ChannelDispatcherBase* channel_dispatcher) {
+  DCHECK(&video_stats_dispatcher_ == channel_dispatcher);
+  LOG(WARNING) << "video_stats channel was closing";
+}
+
 void WebrtcVideoStream::CaptureNextFrame() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   if (capture_pending_ || encode_pending_) {
     VLOG(1) << "Capture/encode still pending..";
     return;
   }
 
+  base::TimeTicks now = base::TimeTicks::Now();
+
   capture_pending_ = true;
   VLOG(1) << "Capture next frame after "
           << (base::TimeTicks::Now() - last_capture_started_ticks_)
                  .InMilliseconds();
-  last_capture_started_ticks_ = base::TimeTicks::Now();
+  last_capture_started_ticks_ = now;
+
+
+  // |next_frame_timestamps_| is not set if no input events were received since
+  // the previous frame. In that case create FrameTimestamps instance without
+  // setting |input_event_client_timestamp| and |input_event_received_time|.
+  if (!next_frame_timestamps_)
+    next_frame_timestamps_.reset(new FrameTimestamps());
+
+  captured_frame_timestamps_ = std::move(next_frame_timestamps_);
+  captured_frame_timestamps_->capture_started_time = now;
+
   capturer_->Capture(webrtc::DesktopRegion());
 }
 
-void WebrtcVideoStream::OnFrameEncoded(std::unique_ptr<VideoPacket> packet) {
+// static
+WebrtcVideoStream::PacketWithTimestamps WebrtcVideoStream::EncodeFrame(
+    VideoEncoder* encoder,
+    std::unique_ptr<webrtc::DesktopFrame> frame,
+    std::unique_ptr<WebrtcVideoStream::FrameTimestamps> timestamps,
+    uint32_t target_bitrate_kbps,
+    bool key_frame_request) {
+  PacketWithTimestamps result;
+  result.timestamps = std::move(timestamps);
+  result.timestamps->encode_started_time = base::TimeTicks::Now();
+
+  encoder->UpdateTargetBitrate(target_bitrate_kbps);
+  result.packet = encoder->Encode(
+      *frame, key_frame_request ? VideoEncoder::REQUEST_KEY_FRAME : 0);
+
+  result.timestamps->encode_ended_time = base::TimeTicks::Now();
+
+  return result;
+}
+
+void WebrtcVideoStream::OnFrameEncoded(PacketWithTimestamps packet) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   encode_pending_ = false;
-  if (!packet)
-    return;
-  base::TimeTicks current = base::TimeTicks::Now();
-  float encoded_bits = packet->data().size() * 8.0;
+
+  size_t packet_size = packet.packet ? packet.packet->data().size() : 0;
+
+  // Generate HostFrameStats.
+  HostFrameStats stats;
+  stats.frame_size = packet_size;
+  stats.latest_event_timestamp = base::TimeTicks::FromInternalValue(
+      packet.timestamps->input_event_client_timestamp);
+
+  if (!packet.timestamps->input_event_received_time.is_null()) {
+    stats.capture_pending_delay = packet.timestamps->capture_started_time -

[Irfan, 2016/08/09 17:00:37]

update capture_pending_delay when there is no input event ?

[Sergey Ulanov, 2016/08/10 18:07:45]

capture_pending_delay is defined as the delay between the moment an input event
is injected and the next frame is captured. If the frame wasn't preceded with an
input event then we don't want to set this value.

+                                  packet.timestamps->input_event_received_time;
+    stats.latest_event_timestamp = base::TimeTicks::FromInternalValue(

[Irfan, 2016/08/09 17:00:37]

This is duplicated above

[Sergey Ulanov, 2016/08/10 18:07:45]

Removed it from above.

+        packet.timestamps->input_event_client_timestamp);
+  }
+
+  stats.capture_delay = packet.timestamps->capture_delay;
+  stats.capture_overhead_delay = (packet.timestamps->capture_ended_time -

[Irfan, 2016/08/09 17:00:37]

Will be helpful to comment what capture_overhead_delay captures.

[Sergey Ulanov, 2016/08/10 18:07:45]

Done.

+                                  packet.timestamps->capture_started_time) -
+                                 stats.capture_delay;
+
+  stats.encode_pending_delay = packet.timestamps->encode_started_time -
+                               packet.timestamps->capture_ended_time;
+
+  stats.encode_delay = packet.timestamps->encode_ended_time -
+                       packet.timestamps->encode_started_time;
+
+  // TODO(sergeyu): Figure out how to measure send_pending time with WebRTC and
+  // set it here.
+  stats.send_pending_delay = base::TimeDelta();

[Irfan, 2016/08/09 17:00:37]

what is send_pending_delay ? How long webrtc waits before sending ?

[Sergey Ulanov, 2016/08/10 18:07:45]

It may wait if the are other frames in the queue.

+
+  uint32_t frame_id = 0;
+  if (packet.packet) {
+    // Send the frame itself.
+    webrtc::EncodedImageCallback::Result result =
+        webrtc_transport_->video_encoder_factory()->SendEncodedFrame(
+            std::move(packet.packet), packet.timestamps->capture_started_time);
+    if (result.error != webrtc::EncodedImageCallback::Result::OK) {
+      // TODO(sergeyu): Stop the stream.
+      LOG(ERROR) << "Failed to send video frame.";
+      return;
+    }
+    frame_id = result.frame_id;
+  }
+
+  // Send FrameStats message.
+  if (video_stats_dispatcher_.is_connected())
+    video_stats_dispatcher_.OnVideoFrameStats(frame_id, stats);
 
   // Simplistic adaptation of frame polling in the range 5 FPS to 30 FPS.
+  // TODO(sergeyu): Move this logic to a separate class.
+  float encoded_bits = packet_size * 8.0;
   uint32_t next_sched_ms = std::max(
       33, std::min(static_cast<int>(encoded_bits / target_bitrate_kbps_), 200));
-  if (webrtc_transport_->video_encoder_factory()->SendEncodedFrame(
-          std::move(packet)) >= 0) {
-    VLOG(1) << "Send duration "
-            << (base::TimeTicks::Now() - current).InMilliseconds()
-            << ", next sched " << next_sched_ms;
-  } else {
-    LOG(ERROR) << "SendEncodedFrame() failed";
-  }
-  capture_timer_->Start(FROM_HERE,
-                        base::TimeDelta::FromMilliseconds(next_sched_ms), this,
-                        &WebrtcVideoStream::CaptureNextFrame);
+  capture_timer_.Start(FROM_HERE,
+                       base::TimeDelta::FromMilliseconds(next_sched_ms), this,
+                       &WebrtcVideoStream::CaptureNextFrame);
 }
 
 }  // namespace protocol
 }  // namespace remoting