Improve roundtrip stats calculation in the client

Previously decode and rendering time wasn't include the total roundtrip
estimation, which is fixed now. Also moved latency calculation logic to
PerformanceTracker, which allowed to simplify rendering code.

Review URL: https://codereview.chromium.org/1382523002

Cr-Commit-Position: refs/heads/master@{#351850}

9 files changed, 111 insertions, 115 deletions

diff --git a/remoting/client/jni/chromoting_jni_instance.cc b/remoting/client/jni/chromoting_jni_instance.cc
index ba7672b..b12364e 100644
--- a/remoting/client/jni/chromoting_jni_instance.cc
+++ b/remoting/client/jni/chromoting_jni_instance.cc
@@ -292,18 +292,6 @@ void ChromotingJniInstance::SendClientMessage(const std::string& type,
   client_->host_stub()->DeliverClientMessage(extension_message);
 }
 
-void ChromotingJniInstance::RecordPaintTime(int64 paint_time_ms) {
-  if (!jni_runtime_->network_task_runner()->BelongsToCurrentThread()) {
-    jni_runtime_->network_task_runner()->PostTask(
-        FROM_HERE, base::Bind(&ChromotingJniInstance::RecordPaintTime, this,
-                              paint_time_ms));
-    return;
-  }
-
-  if (stats_logging_enabled_)
-    perf_tracker_->RecordPaintTime(paint_time_ms);
-}
-
 void ChromotingJniInstance::OnConnectionState(
     protocol::ConnectionToHost::State state,
     protocol::ErrorCode error) {
diff --git a/remoting/client/jni/chromoting_jni_instance.h b/remoting/client/jni/chromoting_jni_instance.h
index d87aed9..6ec4e40 100644
--- a/remoting/client/jni/chromoting_jni_instance.h
+++ b/remoting/client/jni/chromoting_jni_instance.h
@@ -93,10 +93,6 @@ class ChromotingJniInstance
 
   void SendClientMessage(const std::string& type, const std::string& data);
 
-  // Records paint time for statistics logging, if enabled. May be called from
-  // any thread.
-  void RecordPaintTime(int64 paint_time_ms);
-
   // ClientUserInterface implementation.
   void OnConnectionState(protocol::ConnectionToHost::State state,
                          protocol::ErrorCode error) override;
diff --git a/remoting/client/plugin/pepper_video_renderer_3d.cc b/remoting/client/plugin/pepper_video_renderer_3d.cc
index 83985d4..4d518b6 100644
--- a/remoting/client/plugin/pepper_video_renderer_3d.cc
+++ b/remoting/client/plugin/pepper_video_renderer_3d.cc
@@ -54,11 +54,6 @@ class PepperVideoRenderer3D::Picture {
   PP_VideoPicture picture_;
 };
 
-PepperVideoRenderer3D::FrameDecodeTimestamp::FrameDecodeTimestamp(
-    uint32_t frame_id,
-    base::TimeTicks decode_started_time)
-    : frame_id(frame_id), decode_started_time(decode_started_time) {}
-
 PepperVideoRenderer3D::PepperVideoRenderer3D() : callback_factory_(this) {}
 
 PepperVideoRenderer3D::~PepperVideoRenderer3D() {
@@ -265,14 +260,10 @@ void PepperVideoRenderer3D::DecodeNextPacket() {
   if (!initialization_finished_ || decode_pending_ || pending_packets_.empty())
     return;
 
-  ++latest_frame_id_;
-  frame_decode_timestamps_.push_back(
-      FrameDecodeTimestamp(latest_frame_id_, base::TimeTicks::Now()));
-
   const VideoPacket* packet = pending_packets_.front()->packet();
 
   int32_t result = video_decoder_.Decode(
-      latest_frame_id_, packet->data().size(), packet->data().data(),
+      packet->frame_id(), packet->data().size(), packet->data().data(),
       callback_factory_.NewCallback(&PepperVideoRenderer3D::OnDecodeDone));
   CHECK_EQ(result, PP_OK_COMPLETIONPENDING);
   decode_pending_ = true;
@@ -317,21 +308,7 @@ void PepperVideoRenderer3D::OnPictureReady(int32_t result,
     return;
   }
 
-  CHECK(!frame_decode_timestamps_.empty());
-  const FrameDecodeTimestamp& frame_timer = frame_decode_timestamps_.front();
-
-  if (picture.decode_id != frame_timer.frame_id) {
-    LOG(ERROR)
-        << "Received a video packet that didn't contain a complete frame.";
-    event_handler_->OnVideoDecodeError();
-    return;
-  }
-
-  base::TimeDelta decode_time =
-      base::TimeTicks::Now() - frame_timer.decode_started_time;
-  perf_tracker_->RecordDecodeTime(decode_time.InMilliseconds());
-
-  frame_decode_timestamps_.pop_front();
+  perf_tracker_->OnFrameDecoded(picture.decode_id);
 
   next_picture_.reset(new Picture(&video_decoder_, picture));
 
@@ -348,7 +325,6 @@ void PepperVideoRenderer3D::PaintIfNeeded() {
     current_picture_ = next_picture_.Pass();
 
   force_repaint_ = false;
-  latest_paint_started_time_ = base::TimeTicks::Now();
 
   const PP_VideoPicture& picture = current_picture_->picture();
   PP_Resource graphics_3d = graphics_.pp_resource();
@@ -409,9 +385,7 @@ void PepperVideoRenderer3D::OnPaintDone(int32_t result) {
   CHECK_EQ(result, PP_OK) << "Graphics3D::SwapBuffers() failed";
 
   paint_pending_ = false;
-  base::TimeDelta paint_time =
-      base::TimeTicks::Now() - latest_paint_started_time_;
-  perf_tracker_->RecordPaintTime(paint_time.InMilliseconds());
+  perf_tracker_->OnFramePainted(current_picture_->picture().decode_id);
   PaintIfNeeded();
 }
 
diff --git a/remoting/client/plugin/pepper_video_renderer_3d.h b/remoting/client/plugin/pepper_video_renderer_3d.h
index a624a87..2c229b6 100644
--- a/remoting/client/plugin/pepper_video_renderer_3d.h
+++ b/remoting/client/plugin/pepper_video_renderer_3d.h
@@ -11,7 +11,6 @@
 #include "base/basictypes.h"
 #include "base/callback.h"
 #include "base/memory/scoped_ptr.h"
-#include "base/time/time.h"
 #include "ppapi/cpp/graphics_3d.h"
 #include "ppapi/cpp/instance_handle.h"
 #include "ppapi/cpp/video_decoder.h"
@@ -53,13 +52,6 @@ class PepperVideoRenderer3D : public PepperVideoRenderer,
   class PendingPacket;
   class Picture;
 
-  struct FrameDecodeTimestamp {
-    FrameDecodeTimestamp(uint32_t frame_id,
-                         base::TimeTicks decode_started_time);
-    uint32_t frame_id;
-    base::TimeTicks decode_started_time;
-  };
-
   // Callback for pp::VideoDecoder::Initialize().
   void OnInitialized(int32_t result);
 
@@ -113,15 +105,10 @@ class PepperVideoRenderer3D : public PepperVideoRenderer,
   bool get_picture_pending_ = false;
   bool paint_pending_ = false;
 
-  uint32_t latest_frame_id_ = 0;
-
   // Queue of packets that that have been received, but haven't been passed to
   // the decoder yet.
   std::deque<PendingPacket*> pending_packets_;
 
-  // Timestamps for all frames currently being processed by the decoder.
-  std::deque<FrameDecodeTimestamp> frame_decode_timestamps_;
-
   // The current picture shown on the screen or being rendered. Must be deleted
   // before |video_decoder_|.
   scoped_ptr<Picture> current_picture_;
@@ -134,9 +121,6 @@ class PepperVideoRenderer3D : public PepperVideoRenderer,
   // Set to true if the screen has been resized and needs to be repainted.
   bool force_repaint_ = false;
 
-  // Time the last paint operation was started.
-  base::TimeTicks latest_paint_started_time_;
-
   // The texture type for which |shader_program| was initialized. Can be either
   // 0, GL_TEXTURE_2D, GL_TEXTURE_RECTANGLE_ARB or GL_TEXTURE_EXTERNAL_OES. 0
   // indicates that |shader_program_| hasn't been intialized.
diff --git a/remoting/client/software_video_renderer.cc b/remoting/client/software_video_renderer.cc
index b52db3eac..8172369 100644
--- a/remoting/client/software_video_renderer.cc
+++ b/remoting/client/software_video_renderer.cc
@@ -149,25 +149,23 @@ void SoftwareVideoRenderer::ProcessVideoPacket(scoped_ptr<VideoPacket> packet,
       consumer_->AllocateFrame(source_size_);
   frame->set_dpi(source_dpi_);
 
+  int32_t frame_id = packet->frame_id();
   base::PostTaskAndReplyWithResult(
       decode_task_runner_.get(), FROM_HERE,
       base::Bind(&DoDecodeFrame, decoder_.get(), base::Passed(&packet),
                  base::Passed(&frame)),
       base::Bind(&SoftwareVideoRenderer::RenderFrame,
-                 weak_factory_.GetWeakPtr(), base::TimeTicks::Now(),
-                 done_runner.Release()));
+                 weak_factory_.GetWeakPtr(), frame_id, done_runner.Release()));
 }
 
 void SoftwareVideoRenderer::RenderFrame(
-    base::TimeTicks decode_start_time,
+    int32_t frame_id,
     const base::Closure& done,
     scoped_ptr<webrtc::DesktopFrame> frame) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
-  if (perf_tracker_) {
-    perf_tracker_->RecordDecodeTime(
-        (base::TimeTicks::Now() - decode_start_time).InMilliseconds());
-  }
+  if (perf_tracker_)
+    perf_tracker_->OnFrameDecoded(frame_id);
 
   if (!frame) {
     if (!done.is_null())
@@ -175,20 +173,17 @@ void SoftwareVideoRenderer::RenderFrame(
     return;
   }
 
-  consumer_->DrawFrame(
-      frame.Pass(),
-      base::Bind(&SoftwareVideoRenderer::OnFrameRendered,
-                 weak_factory_.GetWeakPtr(), base::TimeTicks::Now(), done));
+  consumer_->DrawFrame(frame.Pass(),
+                       base::Bind(&SoftwareVideoRenderer::OnFrameRendered,
+                                  weak_factory_.GetWeakPtr(), frame_id, done));
 }
 
-void SoftwareVideoRenderer::OnFrameRendered(base::TimeTicks paint_start_time,
+void SoftwareVideoRenderer::OnFrameRendered(int32_t frame_id,
                                             const base::Closure& done) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
-  if (perf_tracker_) {
-    perf_tracker_->RecordPaintTime(
-        (base::TimeTicks::Now() - paint_start_time).InMilliseconds());
-  }
+  if (perf_tracker_)
+    perf_tracker_->OnFramePainted(frame_id);
 
   if (!done.is_null())
     done.Run();
diff --git a/remoting/client/software_video_renderer.h b/remoting/client/software_video_renderer.h
index 318a3d8..5158e9d 100644
--- a/remoting/client/software_video_renderer.h
+++ b/remoting/client/software_video_renderer.h
@@ -55,11 +55,10 @@ class SoftwareVideoRenderer : public VideoRenderer,
                           const base::Closure& done) override;
 
  private:
-  void RenderFrame(base::TimeTicks decode_start_time,
-                 const base::Closure& done,
-                 scoped_ptr<webrtc::DesktopFrame> frame);
-  void OnFrameRendered(base::TimeTicks paint_start_time,
-                       const base::Closure& done);
+  void RenderFrame(int32_t frame_id,
+                   const base::Closure& done,
+                   scoped_ptr<webrtc::DesktopFrame> frame);
+  void OnFrameRendered(int32_t frame_id, const base::Closure& done);
 
   scoped_refptr<base::SingleThreadTaskRunner> decode_task_runner_;
   FrameConsumer* consumer_;
diff --git a/remoting/protocol/client_event_dispatcher.cc b/remoting/protocol/client_event_dispatcher.cc
index 4f1e51e..9329227 100644
--- a/remoting/protocol/client_event_dispatcher.cc
+++ b/remoting/protocol/client_event_dispatcher.cc
@@ -25,7 +25,7 @@ void ClientEventDispatcher::InjectKeyEvent(const KeyEvent& event) {
   DCHECK(event.has_usb_keycode());
   DCHECK(event.has_pressed());
   EventMessage message;
-  message.set_timestamp(base::Time::Now().ToInternalValue());
+  message.set_timestamp(base::TimeTicks::Now().ToInternalValue());
   message.mutable_key_event()->CopyFrom(event);
   writer()->Write(SerializeAndFrameMessage(message), base::Closure());
 }
@@ -33,21 +33,21 @@ void ClientEventDispatcher::InjectKeyEvent(const KeyEvent& event) {
 void ClientEventDispatcher::InjectTextEvent(const TextEvent& event) {
   DCHECK(event.has_text());
   EventMessage message;
-  message.set_timestamp(base::Time::Now().ToInternalValue());
+  message.set_timestamp(base::TimeTicks::Now().ToInternalValue());
   message.mutable_text_event()->CopyFrom(event);
   writer()->Write(SerializeAndFrameMessage(message), base::Closure());
 }
 
 void ClientEventDispatcher::InjectMouseEvent(const MouseEvent& event) {
   EventMessage message;
-  message.set_timestamp(base::Time::Now().ToInternalValue());
+  message.set_timestamp(base::TimeTicks::Now().ToInternalValue());
   message.mutable_mouse_event()->CopyFrom(event);
   writer()->Write(SerializeAndFrameMessage(message), base::Closure());
 }
 
 void ClientEventDispatcher::InjectTouchEvent(const TouchEvent& event) {
   EventMessage message;
-  message.set_timestamp(base::Time::Now().ToInternalValue());
+  message.set_timestamp(base::TimeTicks::Now().ToInternalValue());
   message.mutable_touch_event()->CopyFrom(event);
   writer()->Write(SerializeAndFrameMessage(message), base::Closure());
 }
diff --git a/remoting/protocol/performance_tracker.cc b/remoting/protocol/performance_tracker.cc
index 283e59b..3ee1a4a 100644
--- a/remoting/protocol/performance_tracker.cc
+++ b/remoting/protocol/performance_tracker.cc
@@ -118,27 +118,29 @@ void PerformanceTracker::RecordVideoPacketStats(const VideoPacket& packet) {
   // Record this received packet, even if it is empty.
   video_packet_rate_.Record(1);
 
-  // Record the RTT, even for empty packets, otherwise input events that
-  // do not cause an on-screen change can give very large, bogus RTTs.
-  if (packet.has_latest_event_timestamp() &&
-      packet.latest_event_timestamp() > latest_input_event_timestamp_) {
-    latest_input_event_timestamp_ = packet.latest_event_timestamp();
-
-    base::TimeDelta round_trip_latency =
-        base::Time::Now() -
-        base::Time::FromInternalValue(packet.latest_event_timestamp());
-
-    round_trip_ms_.Record(round_trip_latency.InMilliseconds());
-
-    uma_custom_times_updater_.Run(
-        kRoundTripLatencyHistogram, round_trip_latency.InMilliseconds(),
-        kLatencyHistogramMinMs, kLatencyHistogramMaxMs,
-        kLatencyHistogramBuckets);
+  FrameTimestamps timestamps;
+  timestamps.time_received = base::TimeTicks::Now();
+  if (packet.has_latest_event_timestamp()) {
+    base::TimeTicks timestamp =
+        base::TimeTicks::FromInternalValue(packet.latest_event_timestamp());
+    // Only use latest_event_timestamp field if it has changed from the
+    // previous frame.
+    if (timestamp > latest_event_timestamp_) {
+      timestamps.latest_event_timestamp = timestamp;
+      latest_event_timestamp_ = timestamp;
+    }
   }
 
   // If the packet is empty, there are no other stats to update.
-  if (!packet.data().size())
+  if (!packet.data().size()) {
+    // Record the RTT, even for empty packets, otherwise input events that
+    // do not cause an on-screen change can give very large, bogus RTTs.
+    RecordRoundTripLatency(timestamps);
     return;
+  }
+
+  DCHECK(packet.has_frame_id());
+  frame_timestamps_[packet.frame_id()] = timestamps;
 
   video_frame_rate_.Record(1);
   video_bandwidth_.Record(packet.data().size());
@@ -188,18 +190,55 @@ void PerformanceTracker::RecordVideoPacketStats(const VideoPacket& packet) {
   }
 }
 
-void PerformanceTracker::RecordDecodeTime(double value) {
-  video_decode_ms_.Record(value);
+void PerformanceTracker::OnFrameDecoded(int32_t frame_id) {
+  FramesTimestampsMap::iterator it = frame_timestamps_.find(frame_id);
+  DCHECK(it != frame_timestamps_.end());
+  it->second.time_decoded = base::TimeTicks::Now();
+  base::TimeDelta delay = it->second.time_decoded - it->second.time_received;
+
+  video_decode_ms_.Record(delay.InMilliseconds());
   uma_custom_times_updater_.Run(
-      kVideoDecodeLatencyHistogram, value, kVideoActionsHistogramsMinMs,
-      kVideoActionsHistogramsMaxMs, kVideoActionsHistogramsBuckets);
+      kVideoDecodeLatencyHistogram, delay.InMilliseconds(),
+      kVideoActionsHistogramsMinMs, kVideoActionsHistogramsMaxMs,
+      kVideoActionsHistogramsBuckets);
 }
 
-void PerformanceTracker::RecordPaintTime(double value) {
-  video_paint_ms_.Record(value);
+void PerformanceTracker::OnFramePainted(int32_t frame_id) {
+  base::TimeTicks now = base::TimeTicks::Now();
+
+  while (!frame_timestamps_.empty() &&
+         frame_timestamps_.begin()->first <= frame_id) {
+    FrameTimestamps& timestamps = frame_timestamps_.begin()->second;
+
+    // time_decoded may be null if OnFrameDecoded() was never called, e.g. if
+    // the frame was dropped or decoding has failed.
+    if (!timestamps.time_decoded.is_null()) {
+      base::TimeDelta delay = now - timestamps.time_decoded;
+      video_paint_ms_.Record(delay.InMilliseconds());
+      uma_custom_times_updater_.Run(
+          kVideoPaintLatencyHistogram, delay.InMilliseconds(),
+          kVideoActionsHistogramsMinMs, kVideoActionsHistogramsMaxMs,
+          kVideoActionsHistogramsBuckets);
+    }
+
+    RecordRoundTripLatency(timestamps);
+    frame_timestamps_.erase(frame_timestamps_.begin());
+  }
+}
+
+void PerformanceTracker::RecordRoundTripLatency(
+    const FrameTimestamps& timestamps) {
+  if (timestamps.latest_event_timestamp.is_null())
+    return;
+
+  base::TimeTicks now = base::TimeTicks::Now();
+  base::TimeDelta round_trip_latency =
+      now - timestamps.latest_event_timestamp;
+
+  round_trip_ms_.Record(round_trip_latency.InMilliseconds());
   uma_custom_times_updater_.Run(
-      kVideoPaintLatencyHistogram, value, kVideoActionsHistogramsMinMs,
-      kVideoActionsHistogramsMaxMs, kVideoActionsHistogramsBuckets);
+      kRoundTripLatencyHistogram, round_trip_latency.InMilliseconds(),
+      kLatencyHistogramMinMs, kLatencyHistogramMaxMs, kLatencyHistogramBuckets);
 }
 
 void PerformanceTracker::UploadRateStatsToUma() {
diff --git a/remoting/protocol/performance_tracker.h b/remoting/protocol/performance_tracker.h
index f1d9aa0..fefb169 100644
--- a/remoting/protocol/performance_tracker.h
+++ b/remoting/protocol/performance_tracker.h
@@ -5,6 +5,8 @@
 #ifndef REMOTING_PROTOCOL_PERFORMANCE_TRACKER_H_
 #define REMOTING_PROTOCOL_PERFORMANCE_TRACKER_H_
 
+#include <map>
+
 #include "base/callback.h"
 #include "base/timer/timer.h"
 #include "remoting/base/rate_counter.h"
@@ -53,8 +55,12 @@ class PerformanceTracker {
   // Record stats for a video-packet.
   void RecordVideoPacketStats(const VideoPacket& packet);
 
-  void RecordDecodeTime(double value);
-  void RecordPaintTime(double value);
+  // Helpers to track decode and paint time. If the render drops some frames
+  // before they are painted then OnFramePainted() records paint time when the
+  // following frame is rendered. OnFramePainted() may be called multiple times,
+  // in which case all calls after the first one are ignored.
+  void OnFrameDecoded(int32_t frame_id);
+  void OnFramePainted(int32_t frame_id);
 
   // Sets callbacks in ChromotingInstance to update a UMA custom counts, custom
   // times or enum histogram.
@@ -66,6 +72,18 @@ class PerformanceTracker {
   void OnPauseStateChanged(bool paused);
 
  private:
+  struct FrameTimestamps {
+    // Set to null for frames that were not sent after a fresh input event.
+    base::TimeTicks latest_event_timestamp;
+
+    base::TimeTicks time_received;
+    base::TimeTicks time_decoded;
+  };
+  typedef std::map<int32_t, FrameTimestamps> FramesTimestampsMap;
+
+  // Helper to record input roundtrip latency after a frame has been painted.
+  void RecordRoundTripLatency(const FrameTimestamps& timestamps);
+
   // Updates frame-rate, packet-rate and bandwidth UMA statistics.
   void UploadRateStatsToUma();
 
@@ -97,8 +115,11 @@ class PerformanceTracker {
   UpdateUmaCustomHistogramCallback uma_custom_times_updater_;
   UpdateUmaEnumHistogramCallback uma_enum_histogram_updater_;
 
-  // The latest input timestamp that a VideoPacket was seen annotated with.
-  int64_t latest_input_event_timestamp_ = 0;
+  // The latest event timestamp that a VideoPacket was seen annotated with.
+  base::TimeTicks latest_event_timestamp_;
+
+  // Stores timestamps for the frames that are currently being processed.
+  FramesTimestampsMap frame_timestamps_;
 
   bool is_paused_ = false;