Log compressed size of HTTP/2 requests.

Protected by FLAGS_chromium_http2_flag_log_compressed_size.

This CL lands server change 133714721 by yasong.

BUG=488484

Review-Url: https://codereview.chromium.org/2367973002
Cr-Commit-Position: refs/heads/master@{#421185}

net/quic/core/quic_header_list.cc

@@ -32,6 +32,13 @@ void QuicHeaderList::OnHeader(base::StringPiece name, base::StringPiece value) {
 
 void QuicHeaderList::OnHeaderBlockEnd(size_t uncompressed_header_bytes) {
   uncompressed_header_bytes_ = uncompressed_header_bytes;
+  compressed_header_bytes_ = uncompressed_header_bytes;
+}
+
+void QuicHeaderList::OnHeaderBlockEnd(size_t uncompressed_header_bytes,
+                                      size_t compressed_header_bytes) {
+  uncompressed_header_bytes_ = uncompressed_header_bytes;
+  compressed_header_bytes_ = compressed_header_bytes;
 }
 
 void QuicHeaderList::Clear() {

net/quic/core/quic_header_list.h

@@ -33,6 +33,8 @@ class NET_EXPORT_PRIVATE QuicHeaderList : public SpdyHeadersHandlerInterface {
   void OnHeaderBlockStart() override;
   void OnHeader(base::StringPiece name, base::StringPiece value) override;
   void OnHeaderBlockEnd(size_t uncompressed_header_bytes) override;
+  void OnHeaderBlockEnd(size_t uncompressed_header_bytes,
+                        size_t compressed_header_bytes) override;
 
   void Clear();
 
@@ -44,11 +46,14 @@ class NET_EXPORT_PRIVATE QuicHeaderList : public SpdyHeadersHandlerInterface {
     return uncompressed_header_bytes_;
   }
 
+  size_t compressed_header_bytes() const { return compressed_header_bytes_; }
+
   std::string DebugString() const;
 
  private:
   std::deque<std::pair<std::string, std::string>> header_list_;
   size_t uncompressed_header_bytes_;
+  size_t compressed_header_bytes_;
 };
 
 }  // namespace net

net/spdy/header_coalescer.h

@@ -20,6 +20,8 @@ class NET_EXPORT_PRIVATE HeaderCoalescer : public SpdyHeadersHandlerInterface {
   void OnHeader(base::StringPiece key, base::StringPiece value) override;
 
   void OnHeaderBlockEnd(size_t uncompressed_header_bytes) override {}
+  void OnHeaderBlockEnd(size_t uncompressed_header_bytes,
+                        size_t compressed_header_bytes) override {}
 
   SpdyHeaderBlock release_headers();
   bool error_seen() const { return error_seen_; }

net/spdy/hpack/hpack_decoder.cc

@@ -89,7 +89,11 @@ bool HpackDecoder::HandleControlFrameHeadersComplete(size_t* compressed_len) {
   }
 
   if (handler_ != nullptr) {
-    handler_->OnHeaderBlockEnd(total_header_bytes_);
+    if (FLAGS_chromium_http2_flag_log_compressed_size) {
+      handler_->OnHeaderBlockEnd(total_header_bytes_, total_parsed_bytes_);
+    } else {
+      handler_->OnHeaderBlockEnd(total_header_bytes_);
+    }
   }
   headers_block_buffer_.clear();
   total_parsed_bytes_ = 0;

net/spdy/spdy_deframer_visitor.cc

@@ -195,6 +195,8 @@ class SpdyTestDeframerImpl : public SpdyTestDeframer,
   void OnHeaderBlockStart() override;
   void OnHeader(StringPiece key, StringPiece value) override;
   void OnHeaderBlockEnd(size_t header_bytes_parsed) override;
+  void OnHeaderBlockEnd(size_t header_bytes_parsed,
+                        size_t compressed_header_bytes_parsed) override;
 
  protected:
   void AtDataEnd();
@@ -842,6 +844,18 @@ void SpdyTestDeframerImpl::OnHeaderBlockEnd(size_t header_bytes_parsed) {
   got_hpack_end_ = true;
 }
 
+void SpdyTestDeframerImpl::OnHeaderBlockEnd(
+    size_t /* header_bytes_parsed */,
+    size_t /* compressed_header_bytes_parsed */) {
+  CHECK(headers_);
+  CHECK(frame_type_ == HEADERS || frame_type_ == CONTINUATION ||
+        frame_type_ == PUSH_PROMISE)
+      << "   frame_type_=" << Http2FrameTypeToString(frame_type_);
+  CHECK(end_);
+  CHECK(!got_hpack_end_);
+  got_hpack_end_ = true;
+}
+
 class LoggingSpdyDeframerDelegate : public SpdyDeframerVisitorInterface {
  public:
   explicit LoggingSpdyDeframerDelegate(

net/spdy/spdy_flags.cc

@@ -6,6 +6,9 @@
 
 namespace net {
 
+// Log compressed size of HTTP/2 requests.
+bool FLAGS_chromium_http2_flag_log_compressed_size = true;
+
 // If true, SpdyFramer uses the new visitor methods OnHeaderFrameStart and
 // OnHeaderFrameEnd.  Fourth attempt.
 bool FLAGS_chromium_http2_flag_spdy_framer_use_new_methods4 = true;

net/spdy/spdy_flags.h

@@ -9,6 +9,7 @@
 
 namespace net {
 
+NET_EXPORT_PRIVATE extern bool FLAGS_chromium_http2_flag_log_compressed_size;
 NET_EXPORT_PRIVATE extern bool
     FLAGS_chromium_http2_flag_spdy_framer_use_new_methods4;
 NET_EXPORT_PRIVATE extern bool

net/spdy/spdy_headers_block_parser.cc

@@ -6,6 +6,7 @@
 
 #include "base/sys_byteorder.h"
 #include "net/spdy/spdy_bug_tracker.h"
+#include "net/spdy/spdy_flags.h"
 
 namespace net {
 namespace {
@@ -113,7 +114,16 @@ bool SpdyHeadersBlockParser::HandleControlFrameHeadersData(
           next_state = READING_KEY_LEN;
         } else {
           next_state = READING_HEADER_BLOCK_LEN;
-          handler_->OnHeaderBlockEnd(total_bytes_received_);
+          if (FLAGS_chromium_http2_flag_log_compressed_size) {
+            // We reach here in two cases: 1) Spdy3 or 2) HTTP/2 without hpack
+            // encoding. For the first case, we just log the uncompressed size
+            // since we are going to deprecate Spdy3 soon. For the second case,
+            // the compressed size is the same as the uncompressed size.
+            handler_->OnHeaderBlockEnd(total_bytes_received_,
+                                       total_bytes_received_);
+          } else {
+            handler_->OnHeaderBlockEnd(total_bytes_received_);
+          }
           stream_id_ = kInvalidStreamId;
           // Expect to have consumed all buffer.
           if (reader.Available() != 0) {

net/spdy/spdy_headers_block_parser_test.cc

@@ -9,11 +9,14 @@
 
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_byteorder.h"
+#include "net/spdy/spdy_flags.h"
 #include "net/spdy/spdy_test_utils.h"
 #include "net/test/gtest_util.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
+using testing::_;
+
 namespace net {
 
 using base::IntToString;
@@ -27,6 +30,7 @@ class MockSpdyHeadersHandler : public SpdyHeadersHandlerInterface {
  public:
   MOCK_METHOD0(OnHeaderBlockStart, void());
   MOCK_METHOD1(OnHeaderBlockEnd, void(size_t bytes));
+  MOCK_METHOD2(OnHeaderBlockEnd, void(size_t bytes, size_t compressed_bytes));
   MOCK_METHOD2(OnHeader, void(StringPiece key, StringPiece value));
 };
 
@@ -118,8 +122,11 @@ TEST_P(SpdyHeadersBlockParserTest, BasicTest) {
                                  StringPiece(expect_value))).Times(1);
 
   string headers(CreateHeaders(1, false));
-  EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
-
+  if (FLAGS_chromium_http2_flag_log_compressed_size) {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length(), _)).Times(1);
+  } else {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  }
   EXPECT_TRUE(parser_->
       HandleControlFrameHeadersData(1, headers.c_str(), headers.length()));
   EXPECT_EQ(SpdyHeadersBlockParser::NO_PARSER_ERROR, parser_->get_error());
@@ -136,7 +143,11 @@ TEST_P(SpdyHeadersBlockParserTest, NullsSupportedTest) {
                                  StringPiece(expect_value))).Times(1);
 
   string headers(CreateHeaders(1, true));
-  EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  if (FLAGS_chromium_http2_flag_log_compressed_size) {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length(), _)).Times(1);
+  } else {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  }
 
   EXPECT_TRUE(parser_->
       HandleControlFrameHeadersData(1, headers.c_str(), headers.length()));
@@ -163,7 +174,11 @@ TEST_P(SpdyHeadersBlockParserTest, MultipleBlocksAndHeadersWithPartialData) {
           StringPiece(retained_arguments[2 * j]),
           StringPiece(retained_arguments[2 * j + 1]))).Times(1);
     }
-    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+    if (FLAGS_chromium_http2_flag_log_compressed_size) {
+      EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length(), _)).Times(1);
+    } else {
+      EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+    }
   }
   // Parse the header blocks, feeding the parser one byte at a time.
   for (int i = 1; i <= kNumHeaderBlocks; i++) {
@@ -190,7 +205,11 @@ TEST_P(SpdyHeadersBlockParserTest, HandlesEmptyCallsTest) {
                                  StringPiece(expect_value))).Times(1);
 
   string headers(CreateHeaders(1, false));
-  EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  if (FLAGS_chromium_http2_flag_log_compressed_size) {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length(), _)).Times(1);
+  } else {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  }
 
   // Send a header in pieces with intermediate empty calls.
   for (string::iterator it = headers.begin(); it != headers.end(); ++it) {
@@ -236,7 +255,11 @@ TEST_P(SpdyHeadersBlockParserTest, ExtraDataTest) {
                                  StringPiece(expect_value))).Times(1);
 
   string headers = CreateHeaders(1, false) + "foobar";
-  EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  if (FLAGS_chromium_http2_flag_log_compressed_size) {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length(), _)).Times(1);
+  } else {
+    EXPECT_CALL(handler_, OnHeaderBlockEnd(headers.length())).Times(1);
+  }
 
   EXPECT_FALSE(parser_->HandleControlFrameHeadersData(1, headers.c_str(),
                                                       headers.length()));

net/spdy/spdy_headers_handler_interface.h

@@ -27,10 +27,18 @@ class NET_EXPORT_PRIVATE SpdyHeadersHandlerInterface {
   // values for a given key will be emitted as multiple calls to OnHeader.
   virtual void OnHeader(base::StringPiece key, base::StringPiece value) = 0;
 
+  // TODO(yasong): deprecate this method with
+  // --gfe2_reloadable_flag_log_compressed_size.
   // A callback method which notifies when the parser finishes handling a
   // header block (i.e. the containing frame has the END_HEADERS flag set).
   // Also indicates the total number of bytes in this block.
   virtual void OnHeaderBlockEnd(size_t uncompressed_header_bytes) = 0;
+
+  // A callback method which notifies when the parser finishes handling a
+  // header block (i.e. the containing frame has the END_HEADERS flag set).
+  // Also indicates the total number of bytes in this block.
+  virtual void OnHeaderBlockEnd(size_t uncompressed_header_bytes,
+                                size_t compressed_header_bytes) = 0;
 };
 
 }  // namespace net

net/spdy/spdy_no_op_visitor.h

@@ -87,6 +87,8 @@ class SpdyNoOpVisitor : public SpdyFramerVisitorInterface,
   void OnHeaderBlockStart() override {}
   void OnHeader(base::StringPiece key, base::StringPiece value) override {}
   void OnHeaderBlockEnd(size_t uncompressed_header_bytes) override {}
+  void OnHeaderBlockEnd(size_t /* uncompressed_header_bytes */,
+                        size_t /* compressed_header_bytes */) override {}
 };
 
 }  // namespace test

net/spdy/spdy_test_utils.cc

@@ -183,5 +183,11 @@ void TestHeadersHandler::OnHeaderBlockEnd(size_t header_bytes_parsed) {
   header_bytes_parsed_ = header_bytes_parsed;
 }
 
+void TestHeadersHandler::OnHeaderBlockEnd(
+    size_t header_bytes_parsed,
+    size_t /* compressed_header_bytes_parsed */) {
+  header_bytes_parsed_ = header_bytes_parsed;
+}
+
 }  // namespace test
 }  // namespace net

net/spdy/spdy_test_utils.h

@@ -76,6 +76,9 @@ class TestHeadersHandler : public SpdyHeadersHandlerInterface {
 
   void OnHeaderBlockEnd(size_t header_bytes_parsed) override;
 
+  void OnHeaderBlockEnd(size_t header_bytes_parsed,
+                        size_t /* compressed_header_bytes_parsed */) override;
+
   const SpdyHeaderBlock& decoded_block() const { return block_; }
   size_t header_bytes_parsed() { return header_bytes_parsed_; }