Report capture and encode time for chromoting

Add hooks to record these numbers and report them in the client.

BUG=None
TEST=None

Review URL: http://codereview.chromium.org/6767009

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@80516 0039d316-1c4b-4281-b951-d872f2087c98

14 files changed, 87 insertions, 23 deletions

diff --git a/remoting/base/capture_data.cc b/remoting/base/capture_data.cc
index 15f312e..d8db73a 100644
--- a/remoting/base/capture_data.cc
+++ b/remoting/base/capture_data.cc
@@ -17,7 +17,7 @@ CaptureData::CaptureData(const DataPlanes &data_planes,
                          const gfx::Size& size,
                          media::VideoFrame::Format format) :
     data_planes_(data_planes), dirty_rects_(), size_(size),
-    pixel_format_(format) {
+    pixel_format_(format), capture_time_ms_(0) {
 }
 
 CaptureData::~CaptureData() {}
diff --git a/remoting/base/capture_data.h b/remoting/base/capture_data.h
index 7169914..43909db 100644
--- a/remoting/base/capture_data.h
+++ b/remoting/base/capture_data.h
@@ -46,12 +46,23 @@ class CaptureData : public base::RefCountedThreadSafe<CaptureData> {
   // Mutating methods.
   InvalidRects& mutable_dirty_rects() { return dirty_rects_; }
 
+  // Return the time spent on capturing.
+  int capture_time_ms() const { return capture_time_ms_; }
+
+  // Set the time spent on capturing.
+  void set_capture_time_ms(int capture_time_ms) {
+    capture_time_ms_ = capture_time_ms;
+  }
+
  private:
   const DataPlanes data_planes_;
   InvalidRects dirty_rects_;
   gfx::Size size_;
   media::VideoFrame::Format pixel_format_;
 
+  // Time spent in capture. Unit is in milliseconds.
+  int capture_time_ms_;
+
   friend class base::RefCountedThreadSafe<CaptureData>;
   virtual ~CaptureData();
 };
diff --git a/remoting/base/encoder_row_based.cc b/remoting/base/encoder_row_based.cc
index d740e27..790463f 100644
--- a/remoting/base/encoder_row_based.cc
+++ b/remoting/base/encoder_row_based.cc
@@ -117,6 +117,7 @@ void EncoderRowBased::EncodeRect(const gfx::Rect& rect, bool last) {
     // We have reached the end of stream.
     if (!compress_again) {
       packet->set_flags(packet->flags() | VideoPacket::LAST_PACKET);
+      packet->set_capture_time_ms(capture_data_->capture_time_ms());
       if (last)
         packet->set_flags(packet->flags() | VideoPacket::LAST_PARTITION);
       DCHECK(row_pos == row_size);
diff --git a/remoting/base/encoder_vp8.cc b/remoting/base/encoder_vp8.cc
index 6c10a2c..0d24f7d 100644
--- a/remoting/base/encoder_vp8.cc
+++ b/remoting/base/encoder_vp8.cc
@@ -267,6 +267,7 @@ void EncoderVp8::Encode(scoped_refptr<CaptureData> capture_data,
                      VideoPacket::LAST_PARTITION);
   message->mutable_format()->set_screen_width(capture_data->size().width());
   message->mutable_format()->set_screen_height(capture_data->size().height());
+  message->set_capture_time_ms(capture_data->capture_time_ms());
   for (size_t i = 0; i < updated_rects.size(); ++i) {
     Rect* rect = message->add_dirty_rects();
     rect->set_x(updated_rects[i].x());
diff --git a/remoting/client/chromoting_client.cc b/remoting/client/chromoting_client.cc
index cdfd4ab..2e4e7334 100644
--- a/remoting/client/chromoting_client.cc
+++ b/remoting/client/chromoting_client.cc
@@ -132,6 +132,12 @@ void ChromotingClient::ProcessVideoPacket(const VideoPacket* packet,
   // Record size of the packet for statistics.
   stats_.video_bandwidth()->Record(packet->data().size());
 
+  // Record statistics received from host.
+  if (packet->has_capture_time_ms())
+    stats_.video_capture_ms()->Record(packet->capture_time_ms());
+  if (packet->has_encode_time_ms())
+    stats_.video_encode_ms()->Record(packet->encode_time_ms());
+
   received_packets_.push_back(QueuedVideoPacket(packet, done));
   if (!packet_being_processed_)
     DispatchPacket();
@@ -214,9 +220,10 @@ void ChromotingClient::OnPacketDone(bool last_packet,
 
   TraceContext::tracer()->PrintString("Packet done");
 
-  // Record the latency between the last packet being received and presented.
+  // Record the latency between the final packet being received and
+  // presented.
   if (last_packet) {
-    stats_.video_decode()->Record(
+    stats_.video_decode_ms()->Record(
         (base::Time::Now() - decode_start).InMilliseconds());
   }
 
diff --git a/remoting/client/chromoting_client.h b/remoting/client/chromoting_client.h
index 9670a94..31dd631 100644
--- a/remoting/client/chromoting_client.h
+++ b/remoting/client/chromoting_client.h
@@ -106,8 +106,8 @@ class ChromotingClient : public protocol::ConnectionToHost::HostEventCallback,
   void DispatchPacket();
 
   // Callback method when a VideoPacket is processed.
-  // If |last_packet| is true when |decode_start| contains the timestamp when
-  // the packet starts to be processed.
+  // If |last_packet| is true then |decode_start| contains the timestamp when
+  // the packet will start to be processed.
   void OnPacketDone(bool last_packet, base::Time decode_start);
 
   // The following are not owned by this class.
diff --git a/remoting/client/chromoting_stats.cc b/remoting/client/chromoting_stats.cc
index 4305e61..a9b10e1 100644
--- a/remoting/client/chromoting_stats.cc
+++ b/remoting/client/chromoting_stats.cc
@@ -6,8 +6,11 @@
 
 namespace {
 
-// The default window of bandwidth in seconds.
+// The default window of bandwidth in seconds. Bandwidth is reported as
+// number of numbers received in this time frame.
 static const int kBandwidthWindow = 3;
+
+// We take the last 10 latency numbers and report the average.
 static const int kLatencyWindow = 10;
 
 }  // namespace
@@ -16,8 +19,10 @@ namespace remoting {
 
 ChromotingStats::ChromotingStats()
     : video_bandwidth_(base::TimeDelta::FromSeconds(kBandwidthWindow)),
-      video_decode_(kLatencyWindow),
-      video_paint_(kLatencyWindow) {
+      video_capture_ms_(kLatencyWindow),
+      video_encode_ms_(kLatencyWindow),
+      video_decode_ms_(kLatencyWindow),
+      video_paint_ms_(kLatencyWindow) {
 }
 
 }  // namespace remoting
diff --git a/remoting/client/chromoting_stats.h b/remoting/client/chromoting_stats.h
index 32dd22b..e9f89ff 100644
--- a/remoting/client/chromoting_stats.h
+++ b/remoting/client/chromoting_stats.h
@@ -18,13 +18,17 @@ class ChromotingStats {
   ChromotingStats();
 
   RateCounter* video_bandwidth() { return &video_bandwidth_; }
-  RunningAverage* video_decode() { return &video_decode_; }
-  RunningAverage* video_paint() { return &video_paint_; }
+  RunningAverage* video_capture_ms() { return &video_capture_ms_; }
+  RunningAverage* video_encode_ms() { return &video_encode_ms_; }
+  RunningAverage* video_decode_ms() { return &video_decode_ms_; }
+  RunningAverage* video_paint_ms() { return &video_paint_ms_; }
 
  private:
   RateCounter video_bandwidth_;
-  RunningAverage video_decode_;
-  RunningAverage video_paint_;
+  RunningAverage video_capture_ms_;
+  RunningAverage video_encode_ms_;
+  RunningAverage video_decode_ms_;
+  RunningAverage video_paint_ms_;
 
   DISALLOW_COPY_AND_ASSIGN(ChromotingStats);
 };
diff --git a/remoting/client/plugin/chromoting_scriptable_object.cc b/remoting/client/plugin/chromoting_scriptable_object.cc
index db5fd53..714be1f 100644
--- a/remoting/client/plugin/chromoting_scriptable_object.cc
+++ b/remoting/client/plugin/chromoting_scriptable_object.cc
@@ -28,6 +28,8 @@ const char kSendIq[] = "sendIq";
 const char kQualityAttribute[] = "quality";
 const char kStatusAttribute[] = "status";
 const char kVideoBandwidthAttribute[] = "videoBandwidth";
+const char kVideoCaptureLatencyAttribute[] = "videoCaptureLatency";
+const char kVideoEncodeLatencyAttribute[] = "videoEncodeLatency";
 const char kVideoDecodeLatencyAttribute[] = "videoDecodeLatency";
 const char kVideoRenderLatencyAttribute[] = "videoRenderLatency";
 
@@ -75,6 +77,8 @@ void ChromotingScriptableObject::Init() {
 
   // Statistics.
   AddAttribute(kVideoBandwidthAttribute, Var());
+  AddAttribute(kVideoCaptureLatencyAttribute, Var());
+  AddAttribute(kVideoEncodeLatencyAttribute, Var());
   AddAttribute(kVideoDecodeLatencyAttribute, Var());
   AddAttribute(kVideoRenderLatencyAttribute, Var());
 
@@ -137,15 +141,16 @@ Var ChromotingScriptableObject::GetProperty(const Var& name, Var* exception) {
 
   // If this is a statistics attribute then return the value from
   // ChromotingStats structure.
-  if (name.AsString() == kVideoBandwidthAttribute) {
+  if (name.AsString() == kVideoBandwidthAttribute)
     return instance_->GetStats()->video_bandwidth()->Rate();
-  }
-  else if (name.AsString() == kVideoDecodeLatencyAttribute) {
-    return instance_->GetStats()->video_decode()->Average();
-  }
-  else if (name.AsString() == kVideoRenderLatencyAttribute) {
-    return instance_->GetStats()->video_paint()->Average();
-  }
+  if (name.AsString() == kVideoCaptureLatencyAttribute)
+    return instance_->GetStats()->video_capture_ms()->Average();
+  if (name.AsString() == kVideoEncodeLatencyAttribute)
+    return instance_->GetStats()->video_encode_ms()->Average();
+  if (name.AsString() == kVideoDecodeLatencyAttribute)
+    return instance_->GetStats()->video_decode_ms()->Average();
+  if (name.AsString() == kVideoRenderLatencyAttribute)
+    return instance_->GetStats()->video_paint_ms()->Average();
 
   // TODO(ajwong): This incorrectly return a null object if a function
   // property is requested.
diff --git a/remoting/client/plugin/chromoting_scriptable_object.h b/remoting/client/plugin/chromoting_scriptable_object.h
index d98f37c..bf997b3 100644
--- a/remoting/client/plugin/chromoting_scriptable_object.h
+++ b/remoting/client/plugin/chromoting_scriptable_object.h
@@ -17,9 +17,13 @@
 //   // Statistics.
 //   // Video Bandwidth in bytes per second.
 //   readonly attribute float videoBandwidth;
-//   // Latency for video decoding.
+//   // Latency for capturing in milliseconds.
+//   readonly attribute int videoCaptureLatency;
+//   // Latency for video encoding in milliseconds.
+//   readonly attribute int videoEncodeLatency;
+//   // Latency for video decoding in milliseconds.
 //   readonly attribute int videoDecodeLatency;
-//   // Latency for rendering.
+//   // Latency for rendering in milliseconds.
 //   readonly attribute int videoRenderLatency;
 //
 //   // Constants for connection status.
diff --git a/remoting/client/plugin/pepper_view.cc b/remoting/client/plugin/pepper_view.cc
index 257ff52b..6dc9a51 100644
--- a/remoting/client/plugin/pepper_view.cc
+++ b/remoting/client/plugin/pepper_view.cc
@@ -253,7 +253,7 @@ void PepperView::OnPartialFrameOutput(media::VideoFrame* frame,
 void PepperView::OnPaintDone(base::Time paint_start) {
   DCHECK(CurrentlyOnPluginThread());
   TraceContext::tracer()->PrintString("Paint flushed");
-  instance_->GetStats()->video_paint()->Record(
+  instance_->GetStats()->video_paint_ms()->Record(
       (base::Time::Now() - paint_start).InMilliseconds());
   return;
 }
diff --git a/remoting/host/screen_recorder.cc b/remoting/host/screen_recorder.cc
index 543408e..8faaf3b0 100644
--- a/remoting/host/screen_recorder.cc
+++ b/remoting/host/screen_recorder.cc
@@ -212,6 +212,7 @@ void ScreenRecorder::DoCapture() {
   DCHECK_LE(recordings_, kMaxRecordings);
 
   // And finally perform one capture.
+  capture_start_time_ = base::Time::Now();
   capturer()->CaptureInvalidRects(
       NewCallback(this, &ScreenRecorder::CaptureDoneCallback));
 }
@@ -224,6 +225,9 @@ void ScreenRecorder::CaptureDoneCallback(
     return;
 
   TraceContext::tracer()->PrintString("Capture Done");
+  int capture_time =
+      (base::Time::Now() - capture_start_time_).InMilliseconds();
+  capture_data->set_capture_time_ms(capture_time);
   encode_loop_->PostTask(
       FROM_HERE,
       NewTracedMethod(this, &ScreenRecorder::DoEncode, capture_data));
@@ -354,6 +358,7 @@ void ScreenRecorder::DoEncode(
   }
 
   TraceContext::tracer()->PrintString("Encode start");
+  encode_start_time_ = base::Time::Now();
   encoder()->Encode(
       capture_data, false,
       NewCallback(this, &ScreenRecorder::EncodedDataAvailableCallback));
@@ -374,6 +379,13 @@ void ScreenRecorder::DoStopOnEncodeThread(Task* done_task) {
 void ScreenRecorder::EncodedDataAvailableCallback(VideoPacket* packet) {
   DCHECK_EQ(encode_loop_, MessageLoop::current());
 
+  bool last = packet->flags() & VideoPacket::LAST_PACKET;
+  if (last) {
+    int encode_time =
+        (base::Time::Now() - encode_start_time_).InMilliseconds();
+    packet->set_encode_time_ms(encode_time);
+  }
+
   network_loop_->PostTask(
       FROM_HERE,
       NewTracedMethod(this, &ScreenRecorder::DoSendVideoPacket, packet));
diff --git a/remoting/host/screen_recorder.h b/remoting/host/screen_recorder.h
index da2dbf1..79eacc7 100644
--- a/remoting/host/screen_recorder.h
+++ b/remoting/host/screen_recorder.h
@@ -11,6 +11,8 @@
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop.h"
+#include "base/scoped_ptr.h"
+#include "base/time.h"
 #include "base/timer.h"
 #include "remoting/base/encoder.h"
 #include "remoting/host/capturer.h"
@@ -194,6 +196,12 @@ class ScreenRecorder : public base::RefCountedThreadSafe<ScreenRecorder> {
   // Number of captures to perform every second. Written on the capture thread.
   double max_rate_;
 
+  // Time when capture is started.
+  base::Time capture_start_time_;
+
+  // Time when encode is started.
+  base::Time encode_start_time_;
+
   DISALLOW_COPY_AND_ASSIGN(ScreenRecorder);
 };
 
diff --git a/remoting/proto/video.proto b/remoting/proto/video.proto
index 245db10..b9bd53c 100644
--- a/remoting/proto/video.proto
+++ b/remoting/proto/video.proto
@@ -85,4 +85,10 @@ message VideoPacket {
   // TODO(hclam): Remove this field when we can obtain this information from
   // libvpx.
   repeated Rect dirty_rects = 6;
+
+  // Time in milliseconds spent in capturing this video frame.
+  optional int32 capture_time_ms = 7;
+
+  // Time in milliseconds spent in encoding this video frame.
+  optional int32 encode_time_ms = 8;
 }