relnote: Measure HOL blocking in QUIC headers stream. Flag protected by quic_measure_headers_hol_bl…

net/quic/quic_headers_stream.cc

 // Copyright 2013 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.
 
 #include "net/quic/quic_headers_stream.h"
 
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/stringprintf.h"
+#include "net/quic/quic_flags.h"
+#include "net/quic/quic_headers_stream.h"
 #include "net/quic/quic_spdy_session.h"
+#include "net/quic/quic_time.h"
 
 using base::StringPiece;
+using net::HTTP2;
+using net::SpdyFrameType;
 using std::string;
 
 namespace net {
 
 namespace {
 
 const QuicStreamId kInvalidStreamId = 0;
 
 }  // namespace
 
@@ skipping 146 matching lines @@
 
   DISALLOW_COPY_AND_ASSIGN(SpdyFramerVisitor);
 };
 
 QuicHeadersStream::QuicHeadersStream(QuicSpdySession* session)
     : ReliableQuicStream(kHeadersStreamId, session),
       spdy_session_(session),
       stream_id_(kInvalidStreamId),
       fin_(false),
       frame_len_(0),
+      measure_headers_hol_blocking_time_(
+          FLAGS_quic_measure_headers_hol_blocking_time),
+      cur_max_timestamp_(QuicTime::Zero()),
+      prev_max_timestamp_(QuicTime::Zero()),
       spdy_framer_(HTTP2),
       spdy_framer_visitor_(new SpdyFramerVisitor(this)) {
   spdy_framer_.set_visitor(spdy_framer_visitor_.get());
   spdy_framer_.set_debug_visitor(spdy_framer_visitor_.get());
   // The headers stream is exempt from connection level flow control.
   DisableConnectionFlowControlForThisStream();
 }
 
 QuicHeadersStream::~QuicHeadersStream() {}
 
@@ skipping 13 matching lines @@
   scoped_ptr<SpdySerializedFrame> frame(
       spdy_framer_.SerializeFrame(headers_frame));
   WriteOrBufferData(StringPiece(frame->data(), frame->size()), false,
                     ack_notifier_delegate);
   return frame->size();
 }
 
 void QuicHeadersStream::OnDataAvailable() {
   char buffer[1024];
   struct iovec iov;
+  QuicTime timestamp(QuicTime::Zero());
   while (true) {
     iov.iov_base = buffer;
     iov.iov_len = arraysize(buffer);
-    if (sequencer()->GetReadableRegions(&iov, 1) != 1) {
-      // No more data to read.
-      break;
+    if (measure_headers_hol_blocking_time_) {
+      if (!sequencer()->GetReadableRegion(&iov, &timestamp)) {
+        // No more data to read.
+        break;
+      }
+      DCHECK(timestamp.IsInitialized());
+      cur_max_timestamp_ = QuicTime::Max(timestamp, cur_max_timestamp_);
+    } else {
+      if (sequencer()->GetReadableRegions(&iov, 1) != 1) {
+        // No more data to read.
+        break;
+      }
     }
     if (spdy_framer_.ProcessInput(static_cast<char*>(iov.iov_base),
                                   iov.iov_len) != iov.iov_len) {
       // Error processing data.
       return;
     }
     sequencer()->MarkConsumed(iov.iov_len);
   }
 }
 
@@ skipping 26 matching lines @@
   fin_ = fin;
 }
 
 void QuicHeadersStream::OnControlFrameHeaderData(SpdyStreamId stream_id,
                                                  const char* header_data,
                                                  size_t len) {
   DCHECK_EQ(stream_id_, stream_id);
   if (len == 0) {
     DCHECK_NE(0u, stream_id_);
     DCHECK_NE(0u, frame_len_);
+    if (measure_headers_hol_blocking_time_) {
+      if (prev_max_timestamp_ > cur_max_timestamp_) {
+        // prev_max_timestamp_ > cur_max_timestamp_ implies that
+        // headers from lower numbered streams actually came off the
+        // wire after headers for the current stream, hence there was
+        // HOL blocking.
+        QuicTime::Delta delta(prev_max_timestamp_.Subtract(cur_max_timestamp_));
+        DVLOG(1) << "stream " << stream_id
+                 << ": Net.QuicSession.HeadersHOLBlockedTime "
+                 << delta.ToMilliseconds();
+        UMA_HISTOGRAM_TIMES(
+            "Net.QuicSession.HeadersHOLBlockedTime",
+            base::TimeDelta::FromMicroseconds(delta.ToMicroseconds()));
+      }
+      prev_max_timestamp_ = std::max(prev_max_timestamp_, cur_max_timestamp_);
+      cur_max_timestamp_ = QuicTime::Zero();
+    }
     spdy_session_->OnStreamHeadersComplete(stream_id_, fin_, frame_len_);
     // Reset state for the next frame.
     stream_id_ = kInvalidStreamId;
     fin_ = false;
     frame_len_ = 0;
   } else {
     spdy_session_->OnStreamHeaders(stream_id_, StringPiece(header_data, len));
   }
 }
 
 void QuicHeadersStream::OnCompressedFrameSize(size_t frame_len) {
   frame_len_ += frame_len;
 }
 
 bool QuicHeadersStream::IsConnected() {
   return session()->connection()->connected();
 }
 
 }  // namespace net