Revert 58541 - Cleanup the LOG(INFO)s out of the SpdyStream. Most of the logging was

redundant, so it is removed.  Next changelist will refactor the way we do
headers from the HttpNetworkTransaction, which will move the header logging
back into the stream.  then I think I'm done.

BUG=53956
TEST=none

Review URL: http://codereview.chromium.org/3331012

TBR=mbelshe@chromium.org
Review URL: http://codereview.chromium.org/3307011

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@58565 0039d316-1c4b-4281-b951-d872f2087c98

2 files changed, 31 insertions, 54 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index d47e575..35159d4 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -677,24 +677,20 @@ EVENT_TYPE(SPDY_SESSION_POOL_REMOVE_SESSION)
 // The begin and end of a SPDY STREAM.
 EVENT_TYPE(SPDY_STREAM)
 
-// Logs that a stream attached to a pushed stream.
-EVENT_TYPE(SPDY_STREAM_ADOPTED_PUSH_STREAM)
+// Measures the time taken to send headers on a stream.
+EVENT_TYPE(SPDY_STREAM_SEND_HEADERS)
 
-// This event indicates that the send window has been updated
-//   {
-//     "id":         <The stream id>,
-//     "delta":      <The window size delta>,
-//     "new_window": <The new window size>,
-//   }
-EVENT_TYPE(SPDY_STREAM_SEND_WINDOW_UPDATE)
+// Measures the time taken to send the body (e.g. a POST) on a stream.
+EVENT_TYPE(SPDY_STREAM_SEND_BODY)
 
-// This event indicates that the recv window has been updated
-//   {
-//     "id":         <The stream id>,
-//     "delta":      <The window size delta>,
-//     "new_window": <The new window size>,
-//   }
-EVENT_TYPE(SPDY_STREAM_RECV_WINDOW_UPDATE)
+// Measures the time taken to send headers on a stream.
+EVENT_TYPE(SPDY_STREAM_RECV_HEADERS)
+
+// Measures the time taken to read the body on a stream.
+EVENT_TYPE(SPDY_STREAM_READ_BODY)
+
+// Logs that a stream attached to a pushed stream.
+EVENT_TYPE(SPDY_STREAM_ADOPTED_PUSH_STREAM)
 
 // ------------------------------------------------------------------------
 // HttpStreamParser
diff --git a/net/spdy/spdy_stream.cc b/net/spdy/spdy_stream.cc
index 88b009d..66ca694 100644
--- a/net/spdy/spdy_stream.cc
+++ b/net/spdy/spdy_stream.cc
@@ -7,35 +7,10 @@
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/singleton.h"
-#include "base/values.h"
 #include "net/spdy/spdy_session.h"
 
 namespace net {
 
-namespace {
-
-class NetLogSpdyStreamWindowUpdateParameter : public NetLog::EventParameters {
- public:
-  NetLogSpdyStreamWindowUpdateParameter(spdy::SpdyStreamId stream_id,
-                                        int delta,
-                                        int window_size)
-      : stream_id_(stream_id), delta_(delta), window_size_(window_size) {}
-  virtual Value* ToValue() const {
-    DictionaryValue* dict = new DictionaryValue();
-    dict->SetInteger("id", static_cast<int>(stream_id_));
-    dict->SetInteger("delta", delta_);
-    dict->SetInteger("window_size", window_size_);
-    return dict;
-  }
- private:
-  const spdy::SpdyStreamId stream_id_;
-  const int delta_;
-  const int window_size_;
-  DISALLOW_COPY_AND_ASSIGN(NetLogSpdyStreamWindowUpdateParameter);
-};
-
-}
-
 SpdyStream::SpdyStream(SpdySession* session,
                        spdy::SpdyStreamId stream_id,
                        bool pushed,
@@ -146,11 +121,11 @@ void SpdyStream::IncreaseSendWindowSize(int delta_window_size) {
     return;
   }
 
+  LOG(INFO) << "Increasing stream " << stream_id_
+            << " send_window_size_ [current:" << send_window_size_ << "]"
+            << " by " << delta_window_size << " bytes";
   send_window_size_ = new_window_size;
 
-  net_log_.AddEvent(NetLog::TYPE_SPDY_STREAM_SEND_WINDOW_UPDATE,
-                    new NetLogSpdyStreamWindowUpdateParameter(stream_id_,
-                        delta_window_size, send_window_size_));
   if (stalled_by_flow_control_) {
     stalled_by_flow_control_ = false;
     io_state_ = STATE_SEND_BODY;
@@ -168,11 +143,10 @@ void SpdyStream::DecreaseSendWindowSize(int delta_window_size) {
   // this call to happen.
   DCHECK_GE(send_window_size_, delta_window_size);
 
+  LOG(INFO) << "Decreasing stream " << stream_id_
+            << " send_window_size_ [current:" << send_window_size_ << "]"
+            << " by " << delta_window_size  << " bytes";
   send_window_size_ -= delta_window_size;
-
-  net_log_.AddEvent(NetLog::TYPE_SPDY_STREAM_SEND_WINDOW_UPDATE,
-                    new NetLogSpdyStreamWindowUpdateParameter(stream_id_,
-                        -delta_window_size, send_window_size_));
 }
 
 void SpdyStream::IncreaseRecvWindowSize(int delta_window_size) {
@@ -184,20 +158,20 @@ void SpdyStream::IncreaseRecvWindowSize(int delta_window_size) {
   if (recv_window_size_ > 0)
     DCHECK(new_window_size > 0);
 
+  LOG(INFO) << "Increasing stream " << stream_id_
+            << " recv_window_size_ [current:" << recv_window_size_ << "]"
+            << " by " << delta_window_size << " bytes";
   recv_window_size_ = new_window_size;
-  net_log_.AddEvent(NetLog::TYPE_SPDY_STREAM_RECV_WINDOW_UPDATE,
-                    new NetLogSpdyStreamWindowUpdateParameter(stream_id_,
-                        delta_window_size, recv_window_size_));
   session_->SendWindowUpdate(stream_id_, delta_window_size);
 }
 
 void SpdyStream::DecreaseRecvWindowSize(int delta_window_size) {
   DCHECK_GE(delta_window_size, 1);
 
+  LOG(INFO) << "Decreasing stream " << stream_id_
+            << " recv_window_size_ [current:" << recv_window_size_ << "]"
+            << " by " << delta_window_size  << " bytes";
   recv_window_size_ -= delta_window_size;
-  net_log_.AddEvent(NetLog::TYPE_SPDY_STREAM_RECV_WINDOW_UPDATE,
-                    new NetLogSpdyStreamWindowUpdateParameter(stream_id_,
-                        -delta_window_size, recv_window_size_));
 
   // Since we never decrease the initial window size, we should never hit
   // a negative |recv_window_size_|, if we do, it's a flow-control violation.
@@ -216,6 +190,7 @@ void SpdyStream::SetRequestTime(base::Time t) {
 
 int SpdyStream::OnResponseReceived(const spdy::SpdyHeaderBlock& response) {
   int rv = OK;
+  LOG(INFO) << "Received response for stream " << stream_id_;
 
   metrics_.StartStream();
 
@@ -243,6 +218,8 @@ int SpdyStream::OnResponseReceived(const spdy::SpdyHeaderBlock& response) {
 
 void SpdyStream::OnDataReceived(const char* data, int length) {
   DCHECK_GE(length, 0);
+  LOG(INFO) << "SpdyStream: Data (" << length << " bytes) received for "
+            << stream_id_;
 
   if (!delegate_ || continue_buffering_data_) {
     // It should be valid for this to happen in the server push case.
@@ -362,16 +339,20 @@ int SpdyStream::DoLoop(int result) {
       // State machine 1: Send headers and body.
       case STATE_SEND_HEADERS:
         CHECK_EQ(OK, result);
+        net_log_.BeginEvent(NetLog::TYPE_SPDY_STREAM_SEND_HEADERS, NULL);
         result = DoSendHeaders();
         break;
       case STATE_SEND_HEADERS_COMPLETE:
+        net_log_.EndEvent(NetLog::TYPE_SPDY_STREAM_SEND_HEADERS, NULL);
         result = DoSendHeadersComplete(result);
         break;
       case STATE_SEND_BODY:
         CHECK_EQ(OK, result);
+        net_log_.BeginEvent(NetLog::TYPE_SPDY_STREAM_SEND_BODY, NULL);
         result = DoSendBody();
         break;
       case STATE_SEND_BODY_COMPLETE:
+        net_log_.EndEvent(NetLog::TYPE_SPDY_STREAM_SEND_BODY, NULL);
         result = DoSendBodyComplete(result);
         break;
       // This is an intermediary waiting state. This state is reached when all