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

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();
 };

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);

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());

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_)

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);
 };
 

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() {

remoting/client/chromoting_stats.h

@@ -23,13 +23,15 @@ 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_;
   RunningAverage video_capture_ms_;
   RunningAverage video_encode_ms_;
   RunningAverage video_decode_ms_;
   RunningAverage video_paint_ms_;
+  RunningAverage round_trip_ms_;
 
   DISALLOW_COPY_AND_ASSIGN(ChromotingStats);
 };

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.

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;

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,

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

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));

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);
 };
 

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;

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;
 }

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.

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();
 

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;

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_;