Send PING to check the status of the SPDY connection.

net/spdy/spdy_session.cc

Index: net/spdy/spdy_session.cc
===================================================================
--- net/spdy/spdy_session.cc	(revision 105385)
+++ net/spdy/spdy_session.cc	(working copy)
@@ -4,6 +4,7 @@
 
 #include "net/spdy/spdy_session.h"
 
+#include "base/auto_reset.h"
 #include "base/basictypes.h"
 #include "base/logging.h"
 #include "base/memory/linked_ptr.h"
@@ -172,6 +173,23 @@
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdyRstParameter);
 };
 
+class NetLogSpdyPingParameter : public NetLog::EventParameters {
+ public:
+  explicit NetLogSpdyPingParameter(uint32 unique_id) : unique_id_(unique_id) {}
+
+  virtual Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    dict->SetInteger("unique_id", unique_id_);
+    return dict;
+  }
+
+ private:
+  ~NetLogSpdyPingParameter() {}

[jar (doing other things), 2011/10/14 19:59:07]

Question for WillChan: Does making this private preclude every destroying an
instance?  (since this class doesn't do the deed).  Does this me we (by design)
leak all such created instances?

[willchan no longer on Chromium, 2011/10/14 22:49:21]

Refcounted

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+  const uint32 unique_id_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdyPingParameter);
+};
+
 class NetLogSpdyGoAwayParameter : public NetLog::EventParameters {
  public:
   NetLogSpdyGoAwayParameter(spdy::SpdyStreamId last_stream_id,
@@ -213,6 +231,18 @@
 // static
 size_t SpdySession::max_concurrent_stream_limit_ = 256;
 
+// static
+bool SpdySession::send_ping_for_every_request_ = false;
+
+// static
+int SpdySession::post_ping_delay_time_ms_ = 1000;
+
+// static
+int SpdySession::check_status_delay_time_ms_ = 10000;
+
+// static
+int SpdySession::hung_interval_ms_ = 10000;
+
 SpdySession::SpdySession(const HostPortProxyPair& host_port_proxy_pair,
                          SpdySessionPool* spdy_session_pool,
                          SpdySettingsStorage* spdy_settings,
@@ -246,6 +276,11 @@
       sent_settings_(false),
       received_settings_(false),
       stalled_streams_(0),
+      pings_in_flight_(0),
+      unique_id_counter_(1),
+      post_ping_pending_(false),
+      check_status_pending_(false),
+      last_sent_was_ping_(false),
       initial_send_window_size_(spdy::kSpdyStreamInitialWindowSize),
       initial_recv_window_size_(spdy::kSpdyStreamInitialWindowSize),
       net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SPDY_SESSION)),
@@ -474,6 +509,8 @@
   const scoped_refptr<SpdyStream>& stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
 
+  SendPing();

[jar (doing other things), 2011/10/14 19:59:07]

We need a better name, since this confused me into thinking ew always send a
ping in front of every message.  Perhaps:

SendPrefacePingIfNoneInFlight()

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+
   scoped_ptr<spdy::SpdySynStreamControlFrame> syn_frame(
       spdy_framer_.CreateSynStream(
           stream_id, 0,
@@ -491,6 +528,7 @@
         make_scoped_refptr(
             new NetLogSpdySynParameter(headers, flags, stream_id, 0)));
   }
+  last_sent_was_ping_ = false;
 
   return ERR_IO_PENDING;
 }
@@ -544,6 +582,7 @@
   scoped_ptr<spdy::SpdyDataFrame> frame(
       spdy_framer_.CreateDataFrame(stream_id, data->data(), len, flags));
   QueueFrame(frame.get(), stream->priority(), stream);
+  last_sent_was_ping_ = false;
   return ERR_IO_PENDING;
 }
 
@@ -571,7 +610,7 @@
     priority = stream->priority();
   }
   QueueFrame(rst_frame.get(), priority, NULL);
-
+  last_sent_was_ping_ = false;
   DeleteStream(stream_id, ERR_SPDY_PROTOCOL_ERROR);
 }
 
@@ -612,6 +651,8 @@
 
   bytes_received_ += bytes_read;
 
+  received_data_time_ = base::TimeTicks::Now();
+
   // The SpdyFramer will use callbacks onto |this| as it parses frames.
   // When errors occur, those callbacks can lead to teardown of all references
   // to |this|, so maintain a reference to self during this call for safe
@@ -1229,6 +1270,9 @@
     case spdy::GOAWAY:
       OnGoAway(*reinterpret_cast<const spdy::SpdyGoAwayControlFrame*>(frame));
       break;
+    case spdy::PING:
+      OnPing(*reinterpret_cast<const spdy::SpdyPingControlFrame*>(frame));
+      break;
     case spdy::SETTINGS:
       OnSettings(
           *reinterpret_cast<const spdy::SpdySettingsControlFrame*>(frame));
@@ -1317,6 +1361,32 @@
   // closed.
 }
 
+void SpdySession::OnPing(const spdy::SpdyPingControlFrame& frame) {
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_PING,
+      make_scoped_refptr(new NetLogSpdyPingParameter(frame.unique_id())));

[jar (doing other things), 2011/10/14 19:59:07]

We probably need to condition this on logging... especially if the new'ed item
would leak otherwise.

WillChan: What am I missing??

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+
+  // Send reponse to a PING from Server.
+  if (frame.unique_id() % 2 == 0) {
+    WritePingFrame();

[jar (doing other things), 2011/10/14 19:59:07]

You need to pass the frame.unique_id

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+    return;
+  }
+
+  --pings_in_flight_;
+  if (pings_in_flight_ < 0) {
+    CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true);
+    return;
+  }
+
+  if (pings_in_flight_ > 0)
+    return;
+
+  if (last_sent_was_ping_)
+    return;
+
+  PlanToSendPostPing();
+}
+
 void SpdySession::OnSettings(const spdy::SpdySettingsControlFrame& frame) {
   spdy::SpdySettings settings;
   if (spdy_framer_.ParseSettings(&frame, &settings)) {
@@ -1374,6 +1444,7 @@
   scoped_ptr<spdy::SpdyWindowUpdateControlFrame> window_update_frame(
       spdy_framer_.CreateWindowUpdate(stream_id, delta_window_size));
   QueueFrame(window_update_frame.get(), stream->priority(), stream);
+  last_sent_was_ping_ = false;

[willchan no longer on Chromium, 2011/10/14 22:49:21]

Why don't we just call this in QueueFrame()? You can identify the frame type
there.

[ramant (doing other things), 2011/10/14 23:42:45]

We don't want to set last_sent_was_ping_ to true when we send ping response for
the ping request from server. Wasn't sure how to differentiate if a ping frame
is client generated vs a response to server.

 }
 
 // Given a cwnd that we would have sent to the server, modify it based on the
@@ -1438,6 +1509,7 @@
       spdy_framer_.CreateSettings(settings));
   sent_settings_ = true;
   QueueFrame(settings_frame.get(), 0, NULL);
+  last_sent_was_ping_ = false;
 }
 
 void SpdySession::HandleSettings(const spdy::SpdySettings& settings) {
@@ -1455,6 +1527,100 @@
   }
 }
 
+void SpdySession::SendPing() {
+  if (pings_in_flight_ || post_ping_pending_ || !send_ping_for_every_request_)

[willchan no longer on Chromium, 2011/10/14 22:49:21]

So, if we are sending a ping for every request, how does that get sent out?

[ramant (doing other things), 2011/10/14 23:42:45]

The variable name is wrong. We don't send ping for every request.

Done.

+    return;
+
+  const base::TimeDelta kInterval =
+      base::TimeDelta::FromMilliseconds(hung_interval_ms_);

[jar (doing other things), 2011/10/14 19:59:07]

This needs a different timer name.  It is really meant to be an optimization to
avoid sending wasteful preface pings (when we just got some data). Perhaps we
could call it:

connection_at_risk_of_loss_ms


If it is zero (the most conservative figure), then we always send the preface
ping (when none are in flight).

It is common for TCP/IP sessions to time out in about 3-5 minutes.  Certainly if
it has been more than 3 minutes, we do want to send a preface ping.

I don't think any connection will time out in under about 10 seconds.  So this
might as well be set to something conservative like 10 seconds.  Later, we could
adjust it to send fewer pings perhaps.  

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+
+  base::TimeTicks now = base::TimeTicks::Now();
+  // If we haven't heard from server, then send a pre-PING.
+  if ((now - received_data_time_) > kInterval)
+    SendPrePing();
+
+  PlanToSendPostPing();
+}
+
+void SpdySession::SendPrePing() {
+  AutoReset<bool> reset(&delayed_write_pending_, true);

[willchan no longer on Chromium, 2011/10/14 22:49:21]

Please explain how this works. How does this coalesce the PING and SYN_STREAM
into the same packet? The SpdySession::WriteSocket() function is still only
calling Socket::Write() with a buffer for a single frame.

[ramant (doing other things), 2011/10/14 23:42:45]

Deleted the AutoReset.  You are right, we are writing into socket for every
frame.

+  WritePingFrame();
+  PlanToCheckStatus();
+  ++pings_in_flight_;

[jar (doing other things), 2011/10/14 19:59:07]

You should pass the next_ping_id_ to WritePingFrame.  Then you can move
++pings_in_flight_ into WritePingFrame(n), and condition it on incrementing only
if we have an odd number.

Similarly, last_sent_was_ping_ can be set in that function (when it is an odd
number).

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+  last_sent_was_ping_ = true;
+}
+
+void SpdySession::SendPostPing() {
+  DCHECK(post_ping_pending_);
+  post_ping_pending_ = false;
+  WritePingFrame();
+  PlanToCheckStatus();
+  ++pings_in_flight_;
+  last_sent_was_ping_ = true;
+}
+
+void SpdySession::PlanToSendPostPing() {
+  if (post_ping_pending_)
+    return;
+
+  post_ping_pending_ = true;
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(&SpdySession::SendPostPing),
+      post_ping_delay_time_ms_);
+}
+
+void SpdySession::PlanToCheckStatus() {
+  if (check_status_pending_)
+    return;
+
+  check_status_pending_ = true;
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(
+          &SpdySession::CheckStatus, base::TimeTicks::Now()),
+      check_status_delay_time_ms_);

[jar (doing other things), 2011/10/14 19:59:07]

This should be our hung_interval_ms (or newer name)

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+}
+
+void SpdySession::WritePingFrame() {
+  scoped_ptr<spdy::SpdyPingControlFrame> ping_frame(
+      spdy_framer_.CreatePingFrame(unique_id_counter_));
+  QueueFrame(ping_frame.get(), SPDY_PRIORITY_HIGHEST, NULL);
+
+  if (net_log().IsLoggingAllEvents()) {
+    net_log().AddEvent(
+        NetLog::TYPE_SPDY_SESSION_PING,
+        make_scoped_refptr(new NetLogSpdyPingParameter(unique_id_counter_)));
+  }
+  unique_id_counter_ += 2;

[jar (doing other things), 2011/10/14 19:59:07]

This is only done if we were sending (an odd number) which will come as an
argument.

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+}
+
+void SpdySession::CheckStatus(base::TimeTicks last_check_time) {
+  // Check if we got a response back for all PINGs we had sent.
+  if (pings_in_flight_ == 0) {
+    check_status_pending_ = false;
+    return;
+  }
+
+  DCHECK(check_status_pending_);
+
+  const base::TimeDelta kHungInterval =
+      base::TimeDelta::FromMilliseconds(hung_interval_ms_);
+  if (received_data_time_ < last_check_time) {
+    DCHECK(base::TimeTicks::Now() - received_data_time_ > kHungInterval);

[jar (doing other things), 2011/10/14 19:59:07]

I think this should be >= kHungInterval

[willchan no longer on Chromium, 2011/10/14 23:13:11]

Can you use DCHECK_GT?

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

[ramant (doing other things), 2011/10/14 23:42:45]

DCHECK_GE was giving errors for TimeDelta arguments (logging.h was trying to
create a string).

+    CloseSessionOnError(net::ERR_SPDY_PING_FAILED, true);
+    return;
+  }
+
+  // Check the status of connection after a delay.
+  base::TimeTicks now = base::TimeTicks::Now();

[jar (doing other things), 2011/10/14 19:59:07]

You mentioned this code might be clearer if you just did the now call up around
line 1606.  You can then calculate time since received_data_time, and subtract
kHungInterval (which is the amount of time you still need to wait).

If that is negative, then we fail and close connection.

If it is positive, then we post delayed task for that amount of tim.

[ramant (doing other things), 2011/10/14 23:42:45]

Done.

+  base::TimeDelta delay = kHungInterval - (now - received_data_time_);
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(&SpdySession::CheckStatus, now),
+      delay.InMilliseconds());
+}
+
 void SpdySession::RecordHistograms() {
   UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPerSession",
                               streams_initiated_count_,