Report decode and render latency for Chromoting

Uses RunningAverage to record these numbers, added JS interface for reporting.

BUG=None
TEST=None

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

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

8 files changed, 57 insertions, 12 deletions

diff --git a/remoting/client/chromoting_client.cc b/remoting/client/chromoting_client.cc
index bf1ad39..cdfd4ab 100644
--- a/remoting/client/chromoting_client.cc
+++ b/remoting/client/chromoting_client.cc
@@ -154,8 +154,16 @@ void ChromotingClient::DispatchPacket() {
   packet_being_processed_ = true;
 
   ScopedTracer tracer("Handle video packet");
+
+  // Measure the latency between the last packet being received and presented.
+  bool last_packet = (packet->flags() & VideoPacket::LAST_PACKET) != 0;
+  base::Time decode_start;
+  if (last_packet)
+    decode_start = base::Time::Now();
+
   rectangle_decoder_->DecodePacket(
-      packet, NewTracedMethod(this, &ChromotingClient::OnPacketDone));
+      packet, NewTracedMethod(this, &ChromotingClient::OnPacketDone,
+                              last_packet, decode_start));
 }
 
 void ChromotingClient::OnConnectionOpened(protocol::ConnectionToHost* conn) {
@@ -194,22 +202,31 @@ void ChromotingClient::SetConnectionState(ConnectionState s) {
   Repaint();
 }
 
-void ChromotingClient::OnPacketDone() {
+void ChromotingClient::OnPacketDone(bool last_packet,
+                                    base::Time decode_start) {
   if (message_loop() != MessageLoop::current()) {
     message_loop()->PostTask(
         FROM_HERE,
-        NewTracedMethod(this, &ChromotingClient::OnPacketDone));
+        NewTracedMethod(this, &ChromotingClient::OnPacketDone,
+                        last_packet, decode_start));
     return;
   }
 
   TraceContext::tracer()->PrintString("Packet done");
 
+  // Record the latency between the last packet being received and presented.
+  if (last_packet) {
+    stats_.video_decode()->Record(
+        (base::Time::Now() - decode_start).InMilliseconds());
+  }
+
   received_packets_.front().done->Run();
   delete received_packets_.front().done;
   received_packets_.pop_front();
 
   packet_being_processed_ = false;
 
+  // Process the next video packet.
   DispatchPacket();
 }
 
diff --git a/remoting/client/chromoting_client.h b/remoting/client/chromoting_client.h
index f936ddb..9670a94 100644
--- a/remoting/client/chromoting_client.h
+++ b/remoting/client/chromoting_client.h
@@ -10,6 +10,7 @@
 #include <list>
 
 #include "base/task.h"
+#include "base/time.h"
 #include "remoting/client/client_config.h"
 #include "remoting/client/chromoting_stats.h"
 #include "remoting/client/chromoting_view.h"
@@ -104,7 +105,10 @@ class ChromotingClient : public protocol::ConnectionToHost::HostEventCallback,
   // |received_packets_| queue.
   void DispatchPacket();
 
-  void OnPacketDone();
+  // 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.
+  void OnPacketDone(bool last_packet, base::Time decode_start);
 
   // The following are not owned by this class.
   ClientConfig config_;
diff --git a/remoting/client/chromoting_stats.cc b/remoting/client/chromoting_stats.cc
index 33f10173bf..4305e61 100644
--- a/remoting/client/chromoting_stats.cc
+++ b/remoting/client/chromoting_stats.cc
@@ -8,13 +8,16 @@ namespace {
 
 // The default window of bandwidth in seconds.
 static const int kBandwidthWindow = 3;
+static const int kLatencyWindow = 10;
 
 }  // namespace
 
 namespace remoting {
 
 ChromotingStats::ChromotingStats()
-    : video_bandwidth_(base::TimeDelta::FromSeconds(kBandwidthWindow)) {
+    : video_bandwidth_(base::TimeDelta::FromSeconds(kBandwidthWindow)),
+      video_decode_(kLatencyWindow),
+      video_paint_(kLatencyWindow) {
 }
 
 }  // namespace remoting
diff --git a/remoting/client/chromoting_stats.h b/remoting/client/chromoting_stats.h
index 171c46e..32dd22b 100644
--- a/remoting/client/chromoting_stats.h
+++ b/remoting/client/chromoting_stats.h
@@ -9,6 +9,7 @@
 #define REMOTING_CLIENT_CHROMOTING_STATS_H_
 
 #include "remoting/base/rate_counter.h"
+#include "remoting/base/running_average.h"
 
 namespace remoting {
 
@@ -17,9 +18,13 @@ class ChromotingStats {
   ChromotingStats();
 
   RateCounter* video_bandwidth() { return &video_bandwidth_; }
+  RunningAverage* video_decode() { return &video_decode_; }
+  RunningAverage* video_paint() { return &video_paint_; }
 
  private:
   RateCounter video_bandwidth_;
+  RunningAverage video_decode_;
+  RunningAverage video_paint_;
 
   DISALLOW_COPY_AND_ASSIGN(ChromotingStats);
 };
diff --git a/remoting/client/plugin/chromoting_scriptable_object.cc b/remoting/client/plugin/chromoting_scriptable_object.cc
index 64d6cd5..db5fd53 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 kVideoDecodeLatencyAttribute[] = "videoDecodeLatency";
+const char kVideoRenderLatencyAttribute[] = "videoRenderLatency";
 
 }  // namespace
 
@@ -73,6 +75,8 @@ void ChromotingScriptableObject::Init() {
 
   // Statistics.
   AddAttribute(kVideoBandwidthAttribute, Var());
+  AddAttribute(kVideoDecodeLatencyAttribute, Var());
+  AddAttribute(kVideoRenderLatencyAttribute, Var());
 
   AddMethod("connect", &ChromotingScriptableObject::DoConnect);
   AddMethod("connectSandboxed",
@@ -136,6 +140,12 @@ Var ChromotingScriptableObject::GetProperty(const Var& name, Var* exception) {
   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();
+  }
 
   // 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 399fb6d..d98f37c 100644
--- a/remoting/client/plugin/chromoting_scriptable_object.h
+++ b/remoting/client/plugin/chromoting_scriptable_object.h
@@ -17,6 +17,10 @@
 //   // Statistics.
 //   // Video Bandwidth in bytes per second.
 //   readonly attribute float videoBandwidth;
+//   // Latency for video decoding.
+//   readonly attribute int videoDecodeLatency;
+//   // Latency for rendering.
+//   readonly attribute int videoRenderLatency;
 //
 //   // Constants for connection status.
 //   const unsigned short STATUS_UNKNOWN = 0;
diff --git a/remoting/client/plugin/pepper_view.cc b/remoting/client/plugin/pepper_view.cc
index 7015c9d..257ff52b 100644
--- a/remoting/client/plugin/pepper_view.cc
+++ b/remoting/client/plugin/pepper_view.cc
@@ -12,6 +12,7 @@
 #include "ppapi/cpp/size.h"
 #include "remoting/base/tracer.h"
 #include "remoting/base/util.h"
+#include "remoting/client/chromoting_stats.h"
 #include "remoting/client/client_context.h"
 #include "remoting/client/plugin/chromoting_instance.h"
 #include "remoting/client/plugin/pepper_util.h"
@@ -68,7 +69,8 @@ void PepperView::Paint() {
     // size!  Otherwise, this will just silently do nothing.
     graphics2d_.ReplaceContents(&image);
     graphics2d_.Flush(TaskToCompletionCallback(
-        task_factory_.NewRunnableMethod(&PepperView::OnPaintDone)));
+        task_factory_.NewRunnableMethod(&PepperView::OnPaintDone,
+                                        base::Time::Now())));
   } else {
     // TODO(ajwong): We need to keep a backing store image of the viewport that
     // has the data here which can be redrawn.
@@ -121,7 +123,8 @@ void PepperView::PaintFrame(media::VideoFrame* frame, UpdatedRects* rects) {
   }
 
   graphics2d_.Flush(TaskToCompletionCallback(
-      task_factory_.NewRunnableMethod(&PepperView::OnPaintDone)));
+      task_factory_.NewRunnableMethod(&PepperView::OnPaintDone,
+                                      base::Time::Now())));
 
   TraceContext::tracer()->PrintString("End Paint Frame.");
 }
@@ -247,12 +250,11 @@ void PepperView::OnPartialFrameOutput(media::VideoFrame* frame,
   delete done;
 }
 
-void PepperView::OnPaintDone() {
+void PepperView::OnPaintDone(base::Time paint_start) {
   DCHECK(CurrentlyOnPluginThread());
-
-  // TODO(ajwong):Probably should set some variable to allow repaints to
-  // actually paint.
   TraceContext::tracer()->PrintString("Paint flushed");
+  instance_->GetStats()->video_paint()->Record(
+      (base::Time::Now() - paint_start).InMilliseconds());
   return;
 }
 
diff --git a/remoting/client/plugin/pepper_view.h b/remoting/client/plugin/pepper_view.h
index 28b3332..30f2527 100644
--- a/remoting/client/plugin/pepper_view.h
+++ b/remoting/client/plugin/pepper_view.h
@@ -54,7 +54,7 @@ class PepperView : public ChromotingView,
                                     Task* done);
 
  private:
-  void OnPaintDone();
+  void OnPaintDone(base::Time paint_start);
   void PaintFrame(media::VideoFrame* frame, UpdatedRects* rects);
 
   // Reference to the creating plugin instance. Needed for interacting with