Send PING to check the status of the SPDY connection.

net/spdy/spdy_session.h

 // Copyright (c) 2011 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.
 
 #ifndef NET_SPDY_SPDY_SESSION_H_
 #define NET_SPDY_SPDY_SESSION_H_
 #pragma once
 
 #include <deque>
 #include <list>
@@ skipping 86 matching lines @@
                                   bool is_secure,
                                   int certificate_error_code);
 
   // Check to see if this SPDY session can support an additional domain.
   // If the session is un-authenticated, then this call always returns true.
   // For SSL-based sessions, verifies that the certificate in use by this
   // session provides authentication for the domain.
   // NOTE:  This function can have false negatives on some platforms.
   bool VerifyDomainAuthentication(const std::string& domain);
 
-  // Send the SYN frame for |stream_id|.
+  // Send the SYN frame for |stream_id|. This also sends PING message to check
+  // the status of the connection.
   int WriteSynStream(
       spdy::SpdyStreamId stream_id,
       RequestPriority priority,
       spdy::SpdyControlFlags flags,
       const linked_ptr<spdy::SpdyHeaderBlock>& headers);
 
   // Write a data frame to the stream.
   // Used to create and queue a data frame for the given stream.
   int WriteStreamData(spdy::SpdyStreamId stream_id, net::IOBuffer* data,
                       int len,
@@ skipping 31 matching lines @@
 
   // Sets the max concurrent streams per session, as a ceiling on any server
   // specific SETTINGS value.
   static void set_max_concurrent_streams(size_t value) {
     max_concurrent_stream_limit_ = value;
   }
   static size_t max_concurrent_streams() {
     return max_concurrent_stream_limit_;
   }
 
+  // Enable sending of PING frame with each request.
+  static void set_enable_ping_based_connection_checking(bool enable) {
+    enable_ping_based_connection_checking_ = enable;
+  }
+  static bool enable_ping_based_connection_checking() {
+    return enable_ping_based_connection_checking_;
+  }
+
   // The initial max concurrent streams per session, can be overridden by the
   // server via SETTINGS.
   static void set_init_max_concurrent_streams(size_t value) {
     init_max_concurrent_streams_ =
         std::min(value, max_concurrent_stream_limit_);
   }
 
   // Send WINDOW_UPDATE frame, called by a stream whenever receive window
   // size is increased.
   void SendWindowUpdate(spdy::SpdyStreamId stream_id, int delta_window_size);
@@ skipping 41 matching lines @@
       return unclaimed_pushed_streams_.size();
   }
 
   const BoundNetLog& net_log() const { return net_log_; }
 
   int GetPeerAddress(AddressList* address) const;
   int GetLocalAddress(IPEndPoint* address) const;
 
  private:
   friend class base::RefCounted<SpdySession>;
+  // Allow tests to access our innards for testing purposes.
+  FRIEND_TEST_ALL_PREFIXES(SpdySessionTest, Ping);
   FRIEND_TEST_ALL_PREFIXES(SpdySessionTest, GetActivePushStream);
 
   struct PendingCreateStream {
     PendingCreateStream(const GURL& url, RequestPriority priority,
                         scoped_refptr<SpdyStream>* spdy_stream,
                         const BoundNetLog& stream_net_log,
                         OldCompletionCallback* callback)
         : url(&url), priority(priority), spdy_stream(spdy_stream),
           stream_net_log(&stream_net_log), callback(callback) { }
 
@@ skipping 40 matching lines @@
 
   // Control frame handlers.
   void OnSyn(const spdy::SpdySynStreamControlFrame& frame,
              const linked_ptr<spdy::SpdyHeaderBlock>& headers);
   void OnSynReply(const spdy::SpdySynReplyControlFrame& frame,
                   const linked_ptr<spdy::SpdyHeaderBlock>& headers);
   void OnHeaders(const spdy::SpdyHeadersControlFrame& frame,
                  const linked_ptr<spdy::SpdyHeaderBlock>& headers);
   void OnRst(const spdy::SpdyRstStreamControlFrame& frame);
   void OnGoAway(const spdy::SpdyGoAwayControlFrame& frame);
+  void OnPing(const spdy::SpdyPingControlFrame& frame);
   void OnSettings(const spdy::SpdySettingsControlFrame& frame);
   void OnWindowUpdate(const spdy::SpdyWindowUpdateControlFrame& frame);
 
   // IO Callbacks
   void OnReadComplete(int result);
   void OnWriteComplete(int result);
 
   // Send relevant SETTINGS.  This is generally called on connection setup.
   void SendSettings();
 
   // Handle SETTINGS.  Either when we send settings, or when we receive a
   // SETTINGS ontrol frame, update our SpdySession accordingly.
   void HandleSettings(const spdy::SpdySettings& settings);
 
+  // Send the PING (preface-PING and trailing-PING) frames.
+  void SendPrefacePingIfNoneInFlight();
+
+  // Send PING if there are no PINGs in flight and we haven't heard from server.
+  void SendPrefacePing();
+
+  // Send a PING after delay. Don't post a PING if there is already
+  // a trailing PING pending.
+  void PlanToSendTrailingPing();
+
+  // Send a PING if there is no |trailing_ping_pending_|. This PING verifies
+  // that the requests are being received by the server.
+  void SendTrailingPing();
+
+  // Send the PING frame.
+  void WritePingFrame(uint32 unique_id);
+
+  // Post a CheckPingStatus call after delay. Don't post if there is already
+  // CheckPingStatus running.
+  void PlanToCheckPingStatus();
+
+  // Check the status of the connection. It calls |CloseSessionOnError| if we
+  // haven't received any data in |kHungInterval| time period.
+  void CheckPingStatus(base::TimeTicks last_check_time);
+
   // Start reading from the socket.
   // Returns OK on success, or an error on failure.
   net::Error ReadSocket();
 
   // Write current data to the socket.
   void WriteSocketLater();
   void WriteSocket();
 
   // Get a new stream id.
   int GetNewStreamId();
@@ skipping 37 matching lines @@
                                  const char* data,
                                  size_t len);
   virtual void OnControl(const spdy::SpdyControlFrame* frame);
 
   virtual bool OnControlFrameHeaderData(spdy::SpdyStreamId stream_id,
                                         const char* header_data,
                                         size_t len);
 
   virtual void OnDataFrameHeader(const spdy::SpdyDataFrame* frame);
 
+  // --------------------------
+  // Helper methods for testing
+  // --------------------------
+  static void set_connection_at_risk_of_loss_ms(int duration) {
+    connection_at_risk_of_loss_ms_ = duration;
+  }
+  static int connection_at_risk_of_loss_ms() {
+    return connection_at_risk_of_loss_ms_;
+  }
+
+  static void set_trailing_ping_delay_time_ms(int duration) {
+    trailing_ping_delay_time_ms_ = duration;
+  }
+  static int trailing_ping_delay_time_ms() {
+    return trailing_ping_delay_time_ms_;
+  }
+
+  static void set_hung_interval_ms(int duration) {
+    hung_interval_ms_ = duration;
+  }
+  static int hung_interval_ms() {
+    return hung_interval_ms_;
+  }
+
+  int64 pings_in_flight() const { return pings_in_flight_; }
+
+  uint32 next_ping_id() const { return next_ping_id_; }
+
+  base::TimeTicks received_data_time() const { return received_data_time_; }
+
+  bool trailing_ping_pending() const { return trailing_ping_pending_; }
+
+  bool check_ping_status_pending() const { return check_ping_status_pending_; }
+
   // Callbacks for the Spdy session.
   OldCompletionCallbackImpl<SpdySession> read_callback_;
   OldCompletionCallbackImpl<SpdySession> write_callback_;
 
   // Used for posting asynchronous IO tasks.  We use this even though
   // SpdySession is refcounted because we don't need to keep the SpdySession
   // alive if the last reference is within a RunnableMethod.  Just revoke the
   // method.
   ScopedRunnableMethodFactory<SpdySession> method_factory_;
 
@@ skipping 69 matching lines @@
   int streams_pushed_count_;
   int streams_pushed_and_claimed_count_;
   int streams_abandoned_count_;
   int frames_received_;
   int bytes_received_;
   bool sent_settings_;      // Did this session send settings when it started.
   bool received_settings_;  // Did this session receive at least one settings
                             // frame.
   int stalled_streams_;     // Count of streams that were ever stalled.
 
+  // Count of all pings on the wire, for which we have not gotten a response.
+  int64 pings_in_flight_;
+
+  // This is the next ping_id (unique_id) to be sent in PING frame.
+  uint32 next_ping_id_;
+
+  // This is the last time we have received data.
+  base::TimeTicks received_data_time_;
+
+  // Indicate if we have already scheduled a delayed task to send a trailing
+  // ping (and we never have more than one scheduled at a time).
+  bool trailing_ping_pending_;
+
+  // Indicate if we have already scheduled a delayed task to check the ping
+  // status.
+  bool check_ping_status_pending_;
+
+  // Indicate if the last data we sent was a ping (generally, a trailing ping).
+  // This helps us to decide if we need yet another trailing ping, or if it
+  // would be a waste of effort (and MUST not be done).
+  bool last_sent_was_ping_;
+
   // Initial send window size for the session; can be changed by an
   // arriving SETTINGS frame; newly created streams use this value for the
   // initial send window size.
   int initial_send_window_size_;
 
   // Initial receive window size for the session; there are plans to add a
   // command line switch that would cause a SETTINGS frame with window size
   // announcement to be sent on startup; newly created streams will use
   // this value for the initial receive window size.
   int initial_recv_window_size_;
 
   BoundNetLog net_log_;
 
   // Outside of tests, this should always be true.
   bool verify_domain_authentication_;
 
   static bool use_ssl_;
   static bool use_flow_control_;
   static size_t init_max_concurrent_streams_;
   static size_t max_concurrent_stream_limit_;
+
+  // This enables or disables connection health checking system.
+  static bool enable_ping_based_connection_checking_;
+
+  // |connection_at_risk_of_loss_ms_| is an optimization to avoid sending
+  // wasteful preface pings (when we just got some data).
+  //
+  // 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.
+  //
+  // We 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.
+  static int connection_at_risk_of_loss_ms_;

[willchan no longer on Chromium, 2011/10/15 08:08:03]

Is this a new optimization? I haven't heard about this one.

Raman, in the future, please stop adding changes we haven't discussed beforehand
when we're trying to get changes in by the milestone cutoff. It would have been
much easier if we had gotten the quick and dirty change in right at the get go
and then could relax and get an updated version in later at a more leisurely
schedule.

What's the failure mode of this change? If a NAT router reboots within those 10
seconds and thus we lose the connection mapping in its table, what happens? Will
we ever catch this hang without a user-initiated refresh or something? Is that
reasonable? What about connections for non-user initiated requests? Will those
only time out after many minutes?

[jar (doing other things), 2011/10/15 09:00:52]

Recall that the back-and-forth discussion was about whether to send a preface
ping, or a follower ping. Either one was roughly sufficient, but the preface
ping was helpful in finding out sooner if the channel was long since dead, and
the follower ping was better at providing assurance that the last bytes had
reached the server (and thus justifying an arbitrary wait-for-response (with no
additional pinging).

The argument against a preface ping was that it delays (ever so slightly) the
sending of the first bits of the request.

This logic relating to line 570 simply states that IF we just very recently
received data on the wire, then the preface ping serves no valuable function,
and only delays the data.

Recall that all parties to the discussion agreed that fewer pings were better,
and this parameter allows for reducing the number of pings.  If this is set to
zero, then we always send a preface ping (when we have no current pings in
flight).  Hence it can be set to instigate maximal pinging, or to allow more
conservative (fewer) pings when starting a new session on the back (just after
finishing) receiving data from a previous session.

I think this was in the spirit of all of our discussions.



On 2011/10/15 08:08:03, willchan wrote:

[willchan no longer on Chromium, 2011/10/15 20:17:40]

Please recall http://code.google.com/p/chromium/issues/detail?id=89725#c6 which
makes no mention of this. I'm disappointed we are changing that proposal so late
in the cycle. Were we really planning to discuss this over the weekend prior to
the cutoff?

If you guys really want it, let's do it. Let's not wait another review
roundtrip, let's just get this in. That said, let me express my qualms. In
short, this is premature optimization that violates Keep It Simple Stupid and
may lead to improper handling of exceptional cases.

I feel like this is unnecessary complexity for such a little performance gain.
With the preface and trailer PING frames coming in at 12 bytes each, and the
trailer coming in one second after the preface, that means the maximum PING
overhead is 24 bytes + TLS application record overhead per second. Now, with
this change setting connection_at_risk_of_loss_ms_ to 10s, we are *at best*
saving 9 * (24 bytes + TLS application record overhead) over a 10 second period.
Over 10 seconds, do we really care about saving a few hundred bytes in the
absolute best case?

Now, if a router does reboot or whatever and we send a request out during this 9
second window and don't send anymore requests for the session, that SPDY
connection will hang and not recover until the TCP retransmit timeouts. For
pages, this isn't too big of a deal since it's likely a new request will happen
(more browsing or a refresh or something). For system requests that aren't
driven by users, this is pretty harmful. And we have plenty of those nowadays
which talk to Google over SPDY.

On 2011/10/15 09:00:52, jar wrote:

[jar (doing other things), 2011/10/15 23:25:11]

If you are concerned with it, we can set the time to zero.  It was coded with
that as a viable option.  

Raman wanted to land some histograms to see how often these things would be
useful.  

In a protocol which is deriving a lot of its benefit based on compression,
consistent care about not pushing extra messages or bytes seems to always be
prudent. ...and even if we don't choose to use the knobs, having them close at
hand may prove very helpful.

Note that the expectation is that a follower ping would be sent very soon after
the data.  I'd suggest times for follower ping transmission in the range of
500ms to 1000ms, and hence your mention of 10 seconds is perchance misplaced..

Follower-ping is just used to aggregate a few requests automatically between a
pair of pings, so omission of a preface ping is not a big deal (again, we talked
about *never* sending preface pings, and all parties were ok with it). 
Performing an optimization that sometimes (when it would IMO be embarrassing to
look at a trace and see consecutive follower-ping followed almost immediately by
a preface ping), seems like a reasonable option.

Again, if you're concerned, I'm fine with setting the
"connection_at_risk_of_loss_ms" to be 0.  That means that we're always nervous,
and always send a preface-ping even if we just got back a reply to the last
follower-ping.

Although not appropriate to this CL and goal, the whole use of pings to
stimulate (effectively) acks seems like an element of the protocol that should
have been implicitly provided at a lower level.  Specifically, we could insist
on a server sending ACKs for received data at various times, which would mean
that a ping would never be needed to stimulate such a pseudo-ACK.  Again, this
can't be in this weekend's timeline, but this should be discussed for SPDY 3.


On 2011/10/15 20:17:40, willchan wrote:

[ramant (doing other things), 2011/10/15 23:33:11]

I think it is just variable name change. In patch 14, we were using hunginterval
to send the preface ping in SendPing.

http://codereview.chromium.org/8230037/diff/25001/net/spdy/spdy_session.cc

I am not sure what should be right interval time.

[willchan no longer on Chromium, 2011/10/15 23:52:28]

Great, let's do that.
Agreed. I just don't want to miss the deadline by adding in extra complexity
that is untested (all of this timeout based code is currently untested).
You might want to re-read my comment. I said the trailer PING happens in 1
second. The 10s comes from this new knob added |connection_at_risk_of_loss_ms_|.

[willchan no longer on Chromium, 2011/10/15 23:52:28]

Oh wow, I totally missed that previously. My bad. I didn't see it as one of the
optimizations in http://code.google.com/p/chromium/issues/detail?id=89725, so I
thought it was new.

+
+  // This is the amount of time (in milliseconds) we wait before sending a
+  // trailing ping.

[willchan no longer on Chromium, 2011/10/15 08:08:03]

You should explain why we use a trailing ping.

[jar (doing other things), 2011/10/15 09:00:52]

Suggested comment:

We use a trailing ping (sent after all data) to get an effective acknowlegement
from the server that it has indeed received all (prior) data frames. With that
assurance, we are willing to enter into a wait state for responses to our last
data frame(s) without further pings.

[ramant (doing other things), 2011/10/15 23:33:11]

Done.

+  static int trailing_ping_delay_time_ms_;
+
+  // The amount of time (in milliseconds) that we are willing to tolerate with
+  // no data received (of any form), while there is a ping in flight, before we
+  // declare the connection to be hung.
+  static int hung_interval_ms_;
 };
 
 class NetLogSpdySynParameter : public NetLog::EventParameters {
  public:
   NetLogSpdySynParameter(const linked_ptr<spdy::SpdyHeaderBlock>& headers,
                          spdy::SpdyControlFlags flags,
                          spdy::SpdyStreamId id,
                          spdy::SpdyStreamId associated_stream);
 
   const linked_ptr<spdy::SpdyHeaderBlock>& GetHeaders() const {
     return headers_;
   }
 
   virtual base::Value* ToValue() const;
 
  private:
   virtual ~NetLogSpdySynParameter();
 
   const linked_ptr<spdy::SpdyHeaderBlock> headers_;
   const spdy::SpdyControlFlags flags_;
   const spdy::SpdyStreamId id_;
   const spdy::SpdyStreamId associated_stream_;
 
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdySynParameter);
 };
 
 }  // namespace net
 
 #endif  // NET_SPDY_SPDY_SESSION_H_