Chromoting to report roundtrip latency

Doing so by sending a sequence number, essentially the timestamp in every
envet message. Capturer at the host will pick up the latest sequence number
and pass it through the pipeline. Client will then receive it and determine
the latency.

This roundtrip latency number however doesn't include time in decoding and
rendering.

BUG=None
TEST=None

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

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

22 files changed, 121 insertions, 19 deletions

diff --git a/remoting/base/capture_data.h b/remoting/base/capture_data.h
index 43909db..b8592fa 100644
--- a/remoting/base/capture_data.h
+++ b/remoting/base/capture_data.h
@@ -54,6 +54,12 @@ class CaptureData : public base::RefCountedThreadSafe<CaptureData> {
     capture_time_ms_ = capture_time_ms;
   }
 
+  int64 client_sequence_number() const { return client_sequence_number_; }
+
+  void set_client_sequence_number(int64 client_sequence_number) {
+    client_sequence_number_ = client_sequence_number;
+  }
+
  private:
   const DataPlanes data_planes_;
   InvalidRects dirty_rects_;
@@ -63,6 +69,9 @@ class CaptureData : public base::RefCountedThreadSafe<CaptureData> {
   // Time spent in capture. Unit is in milliseconds.
   int capture_time_ms_;
 
+  // Sequence number supplied by client for performance tracking.
+  int64 client_sequence_number_;
+
   friend class base::RefCountedThreadSafe<CaptureData>;
   virtual ~CaptureData();
 };
diff --git a/remoting/base/encoder_row_based.cc b/remoting/base/encoder_row_based.cc
index 790463f..8039869 100644
--- a/remoting/base/encoder_row_based.cc
+++ b/remoting/base/encoder_row_based.cc
@@ -118,6 +118,8 @@ void EncoderRowBased::EncodeRect(const gfx::Rect& rect, bool last) {
     if (!compress_again) {
       packet->set_flags(packet->flags() | VideoPacket::LAST_PACKET);
       packet->set_capture_time_ms(capture_data_->capture_time_ms());
+      packet->set_client_sequence_number(
+          capture_data_->client_sequence_number());
       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 0d24f7d..84a0bc6 100644
--- a/remoting/base/encoder_vp8.cc
+++ b/remoting/base/encoder_vp8.cc
@@ -268,6 +268,7 @@ void EncoderVp8::Encode(scoped_refptr<CaptureData> capture_data,
   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());
+  message->set_client_sequence_number(capture_data->client_sequence_number());
   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 2e4e7334..697245c 100644
--- a/remoting/client/chromoting_client.cc
+++ b/remoting/client/chromoting_client.cc
@@ -30,7 +30,8 @@ ChromotingClient::ChromotingClient(const ClientConfig& config,
       input_handler_(input_handler),
       client_done_(client_done),
       state_(CREATED),
-      packet_being_processed_(false) {
+      packet_being_processed_(false),
+      last_sequence_number_(0) {
 }
 
 ChromotingClient::~ChromotingClient() {
@@ -137,6 +138,14 @@ void ChromotingClient::ProcessVideoPacket(const VideoPacket* packet,
     stats_.video_capture_ms()->Record(packet->capture_time_ms());
   if (packet->has_encode_time_ms())
     stats_.video_encode_ms()->Record(packet->encode_time_ms());
+  if (packet->has_client_sequence_number() &&
+      packet->client_sequence_number() > last_sequence_number_) {
+    last_sequence_number_ = packet->client_sequence_number();
+    base::TimeDelta round_trip_latency =
+        base::Time::Now() -
+        base::Time::FromInternalValue(packet->client_sequence_number());
+    stats_.round_trip_ms()->Record(round_trip_latency.InMilliseconds());
+  }
 
   received_packets_.push_back(QueuedVideoPacket(packet, done));
   if (!packet_being_processed_)
diff --git a/remoting/client/chromoting_client.h b/remoting/client/chromoting_client.h
index 31dd631..fb785d7 100644
--- a/remoting/client/chromoting_client.h
+++ b/remoting/client/chromoting_client.h
@@ -136,6 +136,9 @@ class ChromotingClient : public protocol::ConnectionToHost::HostEventCallback,
   // Record the statistics of the connection.
   ChromotingStats stats_;
 
+  // Keep track of the last sequence number bounced back from the host.
+  int64 last_sequence_number_;
+
   DISALLOW_COPY_AND_ASSIGN(ChromotingClient);
 };
 
diff --git a/remoting/client/chromoting_stats.cc b/remoting/client/chromoting_stats.cc
index 2fba7c6..9acaedc 100644
--- a/remoting/client/chromoting_stats.cc
+++ b/remoting/client/chromoting_stats.cc
@@ -22,7 +22,8 @@ ChromotingStats::ChromotingStats()
       video_capture_ms_(kLatencyWindow),
       video_encode_ms_(kLatencyWindow),
       video_decode_ms_(kLatencyWindow),
-      video_paint_ms_(kLatencyWindow) {
+      video_paint_ms_(kLatencyWindow),
+      round_trip_ms_(kLatencyWindow) {
 }
 
 ChromotingStats::~ChromotingStats() {
diff --git a/remoting/client/chromoting_stats.h b/remoting/client/chromoting_stats.h
index 174279b..9e91457 100644
--- a/remoting/client/chromoting_stats.h
+++ b/remoting/client/chromoting_stats.h
@@ -23,6 +23,7 @@ class ChromotingStats {
   RunningAverage* video_encode_ms() { return &video_encode_ms_; }
   RunningAverage* video_decode_ms() { return &video_decode_ms_; }
   RunningAverage* video_paint_ms() { return &video_paint_ms_; }
+  RunningAverage* round_trip_ms() { return &round_trip_ms_; }
 
  private:
   RateCounter video_bandwidth_;
@@ -30,6 +31,7 @@ class ChromotingStats {
   RunningAverage video_encode_ms_;
   RunningAverage video_decode_ms_;
   RunningAverage video_paint_ms_;
+  RunningAverage round_trip_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 e2c4126..a12ec53 100644
--- a/remoting/client/plugin/chromoting_scriptable_object.cc
+++ b/remoting/client/plugin/chromoting_scriptable_object.cc
@@ -32,6 +32,7 @@ const char kVideoCaptureLatencyAttribute[] = "videoCaptureLatency";
 const char kVideoEncodeLatencyAttribute[] = "videoEncodeLatency";
 const char kVideoDecodeLatencyAttribute[] = "videoDecodeLatency";
 const char kVideoRenderLatencyAttribute[] = "videoRenderLatency";
+const char kRoundTripLatencyAttribute[] = "roundTripLatency";
 
 }  // namespace
 
@@ -81,6 +82,7 @@ void ChromotingScriptableObject::Init() {
   AddAttribute(kVideoEncodeLatencyAttribute, Var());
   AddAttribute(kVideoDecodeLatencyAttribute, Var());
   AddAttribute(kVideoRenderLatencyAttribute, Var());
+  AddAttribute(kRoundTripLatencyAttribute, Var());
 
   AddMethod("connect", &ChromotingScriptableObject::DoConnect);
   AddMethod("connectSandboxed",
@@ -153,6 +155,8 @@ Var ChromotingScriptableObject::GetProperty(const Var& name, Var* exception) {
     return stats ? stats->video_decode_ms()->Average() : Var();
   if (name.AsString() == kVideoRenderLatencyAttribute)
     return stats ? stats->video_paint_ms()->Average() : Var();
+  if (name.AsString() == kRoundTripLatencyAttribute)
+    return stats ? stats->round_trip_ms()->Average() : Var();
 
   // 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 62f9c68..317d90f 100644
--- a/remoting/client/plugin/chromoting_scriptable_object.h
+++ b/remoting/client/plugin/chromoting_scriptable_object.h
@@ -25,6 +25,9 @@
 //   readonly attribute int videoDecodeLatency;
 //   // Latency for rendering in milliseconds.
 //   readonly attribute int videoRenderLatency;
+//   // Latency between an event is sent and a corresponding video packet is
+//   // received.
+//   readonly attribute int roundTripLatency;
 //
 //   // Constants for connection status.
 //   const unsigned short STATUS_UNKNOWN = 0;
diff --git a/remoting/host/chromoting_host.cc b/remoting/host/chromoting_host.cc
index 6ca4b70..28e28d9 100644
--- a/remoting/host/chromoting_host.cc
+++ b/remoting/host/chromoting_host.cc
@@ -197,6 +197,21 @@ void ChromotingHost::OnConnectionFailed(ConnectionToClient* connection) {
                         make_scoped_refptr(connection)));
 }
 
+void ChromotingHost::OnSequenceNumberUpdated(ConnectionToClient* connection,
+                                             int64 sequence_number) {
+  // Update the sequence number in ScreenRecorder.
+  if (MessageLoop::current() != context_->main_message_loop()) {
+    context_->main_message_loop()->PostTask(
+        FROM_HERE,
+        NewRunnableMethod(this, &ChromotingHost::OnSequenceNumberUpdated,
+                          make_scoped_refptr(connection), sequence_number));
+    return;
+  }
+
+  if (recorder_.get())
+    recorder_->UpdateSequenceNumber(sequence_number);
+}
+
 ////////////////////////////////////////////////////////////////////////////
 // JingleClient::Callback implementations
 void ChromotingHost::OnStateChange(JingleClient* jingle_client,
diff --git a/remoting/host/chromoting_host.h b/remoting/host/chromoting_host.h
index 53fc6c3..4666bcb 100644
--- a/remoting/host/chromoting_host.h
+++ b/remoting/host/chromoting_host.h
@@ -96,6 +96,8 @@ class ChromotingHost : public base::RefCountedThreadSafe<ChromotingHost>,
   virtual void OnConnectionOpened(protocol::ConnectionToClient* client);
   virtual void OnConnectionClosed(protocol::ConnectionToClient* client);
   virtual void OnConnectionFailed(protocol::ConnectionToClient* client);
+  virtual void OnSequenceNumberUpdated(protocol::ConnectionToClient* client,
+                                       int64 sequence_number);
 
   ////////////////////////////////////////////////////////////////////////////
   // JingleClient::Callback implementations
diff --git a/remoting/host/screen_recorder.cc b/remoting/host/screen_recorder.cc
index 37b9c06..4e7355c 100644
--- a/remoting/host/screen_recorder.cc
+++ b/remoting/host/screen_recorder.cc
@@ -50,7 +50,8 @@ ScreenRecorder::ScreenRecorder(
       network_stopped_(false),
       recordings_(0),
       frame_skipped_(false),
-      max_rate_(kDefaultCaptureRate) {
+      max_rate_(kDefaultCaptureRate),
+      sequence_number_(0) {
   DCHECK(capture_loop_);
   DCHECK(encode_loop_);
   DCHECK(network_loop_);
@@ -103,6 +104,19 @@ void ScreenRecorder::RemoveAllConnections() {
       NewTracedMethod(this, &ScreenRecorder::DoRemoveAllClients));
 }
 
+void ScreenRecorder::UpdateSequenceNumber(int64 sequence_number) {
+  // Sequence number is used and written only on the capture thread.
+  if (MessageLoop::current() != capture_loop_) {
+    capture_loop_->PostTask(
+        FROM_HERE,
+        NewRunnableMethod(this, &ScreenRecorder::UpdateSequenceNumber,
+                          sequence_number));
+    return;
+  }
+
+  sequence_number_ = sequence_number;
+}
+
 // Private accessors -----------------------------------------------------------
 
 Capturer* ScreenRecorder::capturer() {
@@ -225,6 +239,14 @@ void ScreenRecorder::CaptureDoneCallback(
   int capture_time = static_cast<int>(
       (base::Time::Now() - capture_start_time_).InMilliseconds());
   capture_data->set_capture_time_ms(capture_time);
+
+  // The best way to get this value is by binding the sequence number to
+  // the callback when calling CaptureInvalidRects(). However the callback
+  // system doesn't allow this. Reading from the member variable is
+  // accurate as long as capture is synchronous as the following statement
+  // will obtain the most recent sequence number received.
+  capture_data->set_client_sequence_number(sequence_number_);
+
   encode_loop_->PostTask(
       FROM_HERE,
       NewTracedMethod(this, &ScreenRecorder::DoEncode, capture_data));
diff --git a/remoting/host/screen_recorder.h b/remoting/host/screen_recorder.h
index ce3e5ce..0426ea7 100644
--- a/remoting/host/screen_recorder.h
+++ b/remoting/host/screen_recorder.h
@@ -11,7 +11,6 @@
 #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"
@@ -104,6 +103,9 @@ class ScreenRecorder : public base::RefCountedThreadSafe<ScreenRecorder> {
   // Remove all connections.
   void RemoveAllConnections();
 
+  // Update the sequence number for tracing performance.
+  void UpdateSequenceNumber(int64 sequence_number);
+
  private:
   // Getters for capturer and encoder.
   Capturer* capturer();
@@ -201,6 +203,9 @@ class ScreenRecorder : public base::RefCountedThreadSafe<ScreenRecorder> {
   // Time when encode is started.
   base::Time encode_start_time_;
 
+  // This is a number updated by client to trace performance.
+  int64 sequence_number_;
+
   DISALLOW_COPY_AND_ASSIGN(ScreenRecorder);
 };
 
diff --git a/remoting/proto/internal.proto b/remoting/proto/internal.proto
index c52dd2d..bee7d03 100644
--- a/remoting/proto/internal.proto
+++ b/remoting/proto/internal.proto
@@ -1,4 +1,4 @@
-// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Copyright (c) 2011 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.
 
@@ -25,7 +25,7 @@ message ControlMessage {
 
 // Defines an event message on the event channel.
 message EventMessage {
-  required int32 timestamp = 1;  // Client timestamp for event
+  required int64 sequence_number = 1;  // Client timestamp for event
   optional bool dummy = 2;       // Is this a dummy event?
 
   optional KeyEvent key_event = 3;
diff --git a/remoting/proto/video.proto b/remoting/proto/video.proto
index b9bd53c..049351e 100644
--- a/remoting/proto/video.proto
+++ b/remoting/proto/video.proto
@@ -1,4 +1,4 @@
-// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Copyright (c) 2011 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.
 
@@ -91,4 +91,8 @@ message VideoPacket {
 
   // Time in milliseconds spent in encoding this video frame.
   optional int32 encode_time_ms = 8;
+
+  // The most recent sequence number received from the client on the event
+  // channel.
+  optional int64 client_sequence_number = 9;
 }
diff --git a/remoting/protocol/connection_to_client.cc b/remoting/protocol/connection_to_client.cc
index 96c11e4..ee2131a 100644
--- a/remoting/protocol/connection_to_client.cc
+++ b/remoting/protocol/connection_to_client.cc
@@ -64,6 +64,10 @@ void ConnectionToClient::Disconnect() {
   }
 }
 
+void ConnectionToClient::UpdateSequenceNumber(int64 sequence_number) {
+  handler_->OnSequenceNumberUpdated(this, sequence_number);
+}
+
 VideoStub* ConnectionToClient::video_stub() {
   return video_writer_.get();
 }
@@ -88,7 +92,7 @@ void ConnectionToClient::OnSessionStateChange(protocol::Session::State state) {
     video_writer_->Init(session_);
 
     dispatcher_.reset(new HostMessageDispatcher());
-    dispatcher_->Initialize(session_.get(), host_stub_, input_stub_);
+    dispatcher_->Initialize(this, host_stub_, input_stub_);
   }
 
   // This method can be called from main thread so perform threading switching.
diff --git a/remoting/protocol/connection_to_client.h b/remoting/protocol/connection_to_client.h
index 19dbdf5..c3f424c 100644
--- a/remoting/protocol/connection_to_client.h
+++ b/remoting/protocol/connection_to_client.h
@@ -11,6 +11,7 @@
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop.h"
+#include "base/synchronization/lock.h"
 #include "remoting/protocol/session.h"
 #include "remoting/protocol/video_writer.h"
 
@@ -42,6 +43,10 @@ class ConnectionToClient :
 
     // Called when the network connection has failed.
     virtual void OnConnectionFailed(ConnectionToClient* connection) = 0;
+
+    // Called when sequence number is updated.
+    virtual void OnSequenceNumberUpdated(ConnectionToClient* connection,
+                                         int64 sequence_number) = 0;
   };
 
   // Constructs a ConnectionToClient object. |message_loop| is the message loop
@@ -62,6 +67,10 @@ class ConnectionToClient :
   // After this method is called all the send method calls will be ignored.
   virtual void Disconnect();
 
+  // Update the sequence number when received from the client. EventHandler
+  // will be called.
+  virtual void UpdateSequenceNumber(int64 sequence_number);
+
   // Send encoded update stream data to the viewer.
   virtual VideoStub* video_stub();
 
diff --git a/remoting/protocol/host_message_dispatcher.cc b/remoting/protocol/host_message_dispatcher.cc
index c793ce7..009dcb3 100644
--- a/remoting/protocol/host_message_dispatcher.cc
+++ b/remoting/protocol/host_message_dispatcher.cc
@@ -26,24 +26,26 @@ HostMessageDispatcher::~HostMessageDispatcher() {
 }
 
 void HostMessageDispatcher::Initialize(
-    protocol::Session* session,
+    ConnectionToClient* connection,
     HostStub* host_stub, InputStub* input_stub) {
-  if (!session || !host_stub || !input_stub ||
-      !session->event_channel() || !session->control_channel()) {
+  if (!connection || !host_stub || !input_stub ||
+      !connection->session()->event_channel() ||
+      !connection->session()->control_channel()) {
     return;
   }
 
   control_message_reader_.reset(new ProtobufMessageReader<ControlMessage>());
   event_message_reader_.reset(new ProtobufMessageReader<EventMessage>());
+  connection_ = connection;
   host_stub_ = host_stub;
   input_stub_ = input_stub;
 
   // Initialize the readers on the sockets provided by channels.
   event_message_reader_->Init(
-      session->event_channel(),
+      connection->session()->event_channel(),
       NewCallback(this, &HostMessageDispatcher::OnEventMessageReceived));
   control_message_reader_->Init(
-      session->control_channel(),
+      connection->session()->control_channel(),
       NewCallback(this, &HostMessageDispatcher::OnControlMessageReceived));
 }
 
@@ -67,6 +69,7 @@ void HostMessageDispatcher::OnControlMessageReceived(
 void HostMessageDispatcher::OnEventMessageReceived(
     EventMessage* message, Task* done_task) {
   // TODO(sergeyu): Add message validation.
+  connection_->UpdateSequenceNumber(message->sequence_number());
   if (message->has_key_event()) {
     input_stub_->InjectKeyEvent(&message->key_event(), done_task);
     return;
diff --git a/remoting/protocol/host_message_dispatcher.h b/remoting/protocol/host_message_dispatcher.h
index 5752f95..67df286 100644
--- a/remoting/protocol/host_message_dispatcher.h
+++ b/remoting/protocol/host_message_dispatcher.h
@@ -13,6 +13,7 @@
 namespace remoting {
 namespace protocol {
 
+class ConnectionToClient;
 class ControlMessage;
 class EventMessage;
 class HostStub;
@@ -37,7 +38,7 @@ class HostMessageDispatcher {
 
   // Initialize the message dispatcher with the given connection and
   // message handlers.
-  void Initialize(protocol::Session* session,
+  void Initialize(ConnectionToClient* connection,
                   HostStub* host_stub, InputStub* input_stub);
 
  private:
@@ -57,6 +58,9 @@ class HostMessageDispatcher {
   // MessageReader that runs on the event channel.
   scoped_ptr<ProtobufMessageReader<EventMessage> > event_message_reader_;
 
+  // Connection that this object belongs to.
+  ConnectionToClient* connection_;
+
   // Stubs for host and input. These objects are not owned.
   // They are called on the thread there data is received, i.e. jingle thread.
   HostStub* host_stub_;
diff --git a/remoting/protocol/input_sender.cc b/remoting/protocol/input_sender.cc
index 8ba90ca..7c9021c 100644
--- a/remoting/protocol/input_sender.cc
+++ b/remoting/protocol/input_sender.cc
@@ -28,16 +28,14 @@ InputSender::~InputSender() {
 
 void InputSender::InjectKeyEvent(const KeyEvent* event, Task* done) {
   EventMessage message;
-  // TODO(hclam): Provide timestamp.
-  message.set_timestamp(0);
+  message.set_sequence_number(base::Time::Now().ToInternalValue());
   message.mutable_key_event()->CopyFrom(*event);
   buffered_writer_->Write(SerializeAndFrameMessage(message), done);
 }
 
 void InputSender::InjectMouseEvent(const MouseEvent* event, Task* done) {
   EventMessage message;
-  // TODO(hclam): Provide timestamp.
-  message.set_timestamp(0);
+  message.set_sequence_number(base::Time::Now().ToInternalValue());
   message.mutable_mouse_event()->CopyFrom(*event);
   buffered_writer_->Write(SerializeAndFrameMessage(message), done);
 }
diff --git a/remoting/protocol/message_decoder_unittest.cc b/remoting/protocol/message_decoder_unittest.cc
index 97c31ff..38526b8 100644
--- a/remoting/protocol/message_decoder_unittest.cc
+++ b/remoting/protocol/message_decoder_unittest.cc
@@ -34,7 +34,7 @@ static void PrepareData(uint8** buffer, int* size) {
   // Then append 10 update sequences to the data.
   for (int i = 0; i < 10; ++i) {
     EventMessage msg;
-    msg.set_timestamp(i);
+    msg.set_sequence_number(i);
     msg.mutable_key_event()->set_keycode(kTestKey + i);
     msg.mutable_key_event()->set_pressed((i % 2) != 0);
     AppendMessage(msg, &encoded_data);
diff --git a/remoting/protocol/protocol_mock_objects.h b/remoting/protocol/protocol_mock_objects.h
index 57dad6a..04105b9 100644
--- a/remoting/protocol/protocol_mock_objects.h
+++ b/remoting/protocol/protocol_mock_objects.h
@@ -46,6 +46,8 @@ class MockConnectionToClientEventHandler :
   MOCK_METHOD1(OnConnectionOpened, void(ConnectionToClient* connection));
   MOCK_METHOD1(OnConnectionClosed, void(ConnectionToClient* connection));
   MOCK_METHOD1(OnConnectionFailed, void(ConnectionToClient* connection));
+  MOCK_METHOD2(OnSequenceNumberUpdated, void(ConnectionToClient* connection,
+                                             int64 sequence_number));
 
  private:
   DISALLOW_COPY_AND_ASSIGN(MockConnectionToClientEventHandler);