Add UMA histograms for more detailed latency tracking on the CRD host.

remoting/host/video_frame_pump.cc

Index: remoting/host/video_frame_pump.cc
diff --git a/remoting/host/video_frame_pump.cc b/remoting/host/video_frame_pump.cc
index 37d9da7c25e1ff47bc6b8bda8bf9488eac436be7..58b72db1ab03bdaaf38dabb44c35217ef6f06027 100644
--- a/remoting/host/video_frame_pump.cc
+++ b/remoting/host/video_frame_pump.cc
@@ -20,28 +20,6 @@
 
 namespace remoting {
 
-namespace {
-
-scoped_ptr<VideoPacket> EncodeFrame(VideoEncoder* encoder,
-                                    scoped_ptr<webrtc::DesktopFrame> frame) {
-  scoped_ptr<VideoPacket> packet;
-
-  // If |frame| is non-NULL then let the encoder process it.
-  if (frame) {
-    packet = encoder->Encode(*frame);
-  }
-
-  // If |frame| is NULL, or the encoder returned nothing, return an empty
-  // packet.
-  if (!packet) {
-    packet.reset(new VideoPacket());
-  }
-
-  return packet.Pass();
-}
-
-}  // namespace
-
 // Interval between empty keep-alive frames. These frames are sent only when the
 // stream is paused or inactive for some other reason (e.g. when blocked on
 // capturer). To prevent PseudoTCP from resetting congestion window this value
@@ -50,6 +28,16 @@ static const int kKeepAlivePacketIntervalMs = 200;
 
 static bool g_enable_timestamps = false;
 
+VideoFramePump::FrameTimestamps::FrameTimestamps() {}
+VideoFramePump::FrameTimestamps::~FrameTimestamps() {}
+
+VideoFramePump::PacketWithTimestamps::PacketWithTimestamps(
+    scoped_ptr<VideoPacket> packet,
+    scoped_ptr<FrameTimestamps> timestamps)
+    : packet(packet.Pass()), timestamps(timestamps.Pass()) {}
+
+VideoFramePump::PacketWithTimestamps::~PacketWithTimestamps() {}
+
 // static
 void VideoFramePump::EnableTimestampsForTests() {
   g_enable_timestamps = true;
@@ -72,7 +60,6 @@ VideoFramePump::VideoFramePump(
           false),
       capture_scheduler_(base::Bind(&VideoFramePump::CaptureNextFrame,
                                     base::Unretained(this))),
-      latest_event_timestamp_(0),
       weak_factory_(this) {
   DCHECK(encoder_);
   DCHECK(video_stub_);
@@ -91,10 +78,13 @@ void VideoFramePump::Pause(bool pause) {
   capture_scheduler_.Pause(pause);
 }
 
-void VideoFramePump::SetLatestEventTimestamp(int64 latest_event_timestamp) {
+void VideoFramePump::OnInputEventReceived(int64_t event_timestamp) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
-  latest_event_timestamp_ = latest_event_timestamp;
+  if (!next_frame_timestamps_)
+    next_frame_timestamps_.reset(new FrameTimestamps());
+  next_frame_timestamps_->input_event_client_timestamp = event_timestamp;
+  next_frame_timestamps_->input_event_received_time = base::TimeTicks::Now();
 }
 
 void VideoFramePump::SetLosslessEncode(bool want_lossless) {
@@ -123,45 +113,126 @@ void VideoFramePump::OnCaptureCompleted(webrtc::DesktopFrame* frame) {
 
   capture_scheduler_.OnCaptureCompleted();
 
+  captured_frame_timestamps_->capture_ended_time = base::TimeTicks::Now();
+
   // Even when |frame| is nullptr we still need to post it to the encode thread
   // to make sure frames are freed in the same order they are received and
   // that we don't start capturing frame n+2 before frame n is freed.
   base::PostTaskAndReplyWithResult(
       encode_task_runner_.get(), FROM_HERE,
-      base::Bind(&EncodeFrame, encoder_.get(),
-                 base::Passed(make_scoped_ptr(frame))),
-      base::Bind(&VideoFramePump::SendEncodedFrame, weak_factory_.GetWeakPtr(),
-                 latest_event_timestamp_, base::TimeTicks::Now()));
+      base::Bind(&VideoFramePump::EncodeFrame, encoder_.get(),
+                 base::Passed(make_scoped_ptr(frame)),
+                 base::Passed(&captured_frame_timestamps_)),
+      base::Bind(&VideoFramePump::OnFrameEncoded, weak_factory_.GetWeakPtr()));
 }
 
 void VideoFramePump::CaptureNextFrame() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
+  // |next_frame_timestamps_| is not set if no input events were received since
+  // the previous frame. In that case create FrameTimestamps instance without
+  // setting |input_event_client_timestamp| and |input_event_received_time|.
+  if (!next_frame_timestamps_)
+    next_frame_timestamps_.reset(new FrameTimestamps());
+
+  captured_frame_timestamps_ = next_frame_timestamps_.Pass();
+  captured_frame_timestamps_->capture_started_time = base::TimeTicks::Now();
+
   capturer_->Capture(webrtc::DesktopRegion());
 }
 
-void VideoFramePump::SendEncodedFrame(int64 latest_event_timestamp,
-                                      base::TimeTicks timestamp,
-                                      scoped_ptr<VideoPacket> packet) {
+// static
+scoped_ptr<VideoFramePump::PacketWithTimestamps> VideoFramePump::EncodeFrame(
+    VideoEncoder* encoder,
+    scoped_ptr<webrtc::DesktopFrame> frame,
+    scoped_ptr<FrameTimestamps> timestamps) {
+  timestamps->encode_started_time = base::TimeTicks::Now();
+
+  scoped_ptr<VideoPacket> packet;
+  // If |frame| is non-NULL then let the encoder process it.
+  if (frame)
+    packet = encoder->Encode(*frame);
+
+  // If |frame| is NULL, or the encoder returned nothing, return an empty
+  // packet.
+  if (!packet)
+    packet.reset(new VideoPacket());
+
+  if (frame)
+    packet->set_capture_time_ms(frame->capture_time_ms());
+
+  timestamps->encode_ended_time = base::TimeTicks::Now();
+
+  return make_scoped_ptr(
+      new PacketWithTimestamps(packet.Pass(), timestamps.Pass()));
+}
+
+void VideoFramePump::OnFrameEncoded(scoped_ptr<PacketWithTimestamps> packet) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
-  if (g_enable_timestamps)
-    packet->set_timestamp(timestamp.ToInternalValue());
+  capture_scheduler_.OnFrameEncoded(packet->packet.get());
 
-  packet->set_latest_event_timestamp(latest_event_timestamp);
+  if (send_pending_) {
+    pending_packets_.push_back(packet.Pass());
+  } else {
+    SendPacket(packet.Pass());
+  }
+}
 
-  capture_scheduler_.OnFrameEncoded(packet.get());
+void VideoFramePump::SendPacket(scoped_ptr<PacketWithTimestamps> packet) {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(!send_pending_);
 
-  video_stub_->ProcessVideoPacket(packet.Pass(),
+  packet->timestamps->can_send_time = base::TimeTicks::Now();
+  UpdateFrameTimers(packet->packet.get(), packet->timestamps.get());
+
+  send_pending_ = true;
+  video_stub_->ProcessVideoPacket(packet->packet.Pass(),
                                   base::Bind(&VideoFramePump::OnVideoPacketSent,
                                              weak_factory_.GetWeakPtr()));
 }
 
+void VideoFramePump::UpdateFrameTimers(VideoPacket* packet,
+                                       FrameTimestamps* timestamps) {
+  if (g_enable_timestamps)
+    packet->set_timestamp(timestamps->capture_ended_time.ToInternalValue());
+
+
+  if (!timestamps->input_event_received_time.is_null()) {
+    packet->set_capture_pending_time_ms((timestamps->capture_started_time -
+                                         timestamps->input_event_received_time)
+                                            .InMilliseconds());
+    packet->set_latest_event_timestamp(
+        timestamps->input_event_client_timestamp);
+  }
+
+  packet->set_capture_overhead_time_ms(
+      (timestamps->capture_ended_time - timestamps->capture_started_time)
+          .InMilliseconds() -
+      packet->capture_time_ms());
+
+  packet->set_encode_pending_time_ms(
+      (timestamps->encode_started_time - timestamps->capture_ended_time)
+          .InMilliseconds());
+
+  packet->set_send_pending_time_ms(
+      (timestamps->can_send_time - timestamps->encode_ended_time)
+          .InMilliseconds());
+}
+
 void VideoFramePump::OnVideoPacketSent() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
+  send_pending_ = false;
   capture_scheduler_.OnFrameSent();
   keep_alive_timer_.Reset();
+
+  // Send next packet if any.
+  if (!pending_packets_.empty()) {
+    scoped_ptr<PacketWithTimestamps> next(pending_packets_.front());
+    pending_packets_.weak_erase(pending_packets_.begin());
+    SendPacket(next.Pass());
+  }
 }
 
 void VideoFramePump::SendKeepAlivePacket() {