Help with "too many connection resets" error

[softwaregravy]

My error is getting raised here.
https://github.com/drbrain/net-http-persistent/blob/master/lib/net/http/persistent.rb#L821

Full error:
"{too many connection resets (due to Timeout::Error - Timeout::Error) after 748740 requests on 69326240, last used 60.068056358 seconds ago\n/app/vendor/bundle/ruby/1.9.1/gems/net-http-persistent-2.5.2/lib/net/http/persistent.rb:821:i

Just trying to understand what I'm doing wrong. I'm probably mis-using the library somehow.

Do I need to be periodically closing connections? Won't they just re-open on an error like this?

Mechanize seems to have a similar issue. It's a long thread, I'm trying to see if there's an overlap.
https://github.com/tenderlove/mechanize/issues/123

[softwaregravy]

I'm digging deeper into this, and the same jobs take longer on subsequent runs, so maybe I need to be closing connections?

2012-03-19T01:57:17+00:00 app[worker.1]: Published 2767 records in 33.88697671890259 seconds
....
2012-03-19T02:06:01+00:00 app[worker.1]: Published 2767 records in 142.7950940132141 seconds

[softwaregravy]

Found the: #shutdown command, which I wasn't using. Adding that to the end of my runs has given me the same 'first run performance'. I did not find the bottleneck. For reference, my jobs ran 10 min apart. Server connecting to is Tomcat7 which has connection expiration configured for never.

[softwaregravy]

Closing in favor of #20

[softwaregravy]

PS, thanks for the library!

[drbrain]

Typically the "too many connection resets" error results when the server has shut down the connection then you try to POST as HTTP does not provide a notification that the connection has terminated, and HTTP does not allow a POST request to be retried by default.

Since you're receiving a Timeout::Error instead, it seems that the server has stopped responding, but has left the connection open, or perhaps after 748,740 requests you wore the poor server out. (I did not notice the amount of requests in the other tickets.)

When you receive other errors like this are they after equally large amounts of requests?

Does adding a manual rescue and retry allow your process to continue?

How many HTTP requests do your worker processes typically make?

[softwaregravy]

it's a batch process that runs every 15 min or so. It makes 10's of thousands.

It was not stopping the process, it was just getting very very slow.

[drbrain]

Does your worker CPU consumption increase as more requests are made?

If this is the case, it's possible mechanize, net-http-persistent, or your code are holding on to some state for too long.

If the CPU time stays the same or becomes reduced, you're probably exposing a bug in the server and #shutdown is the best workaround at present.

PS: I had no idea anyone was using net-http-persistent (or mechanize) this heavily! I'm a little glad to hear of a failure at such scale!

[softwaregravy]

not sure. It's running in Heroku, so I don't monitor cpu, just throughput. My apps have always been governed by the database.

PS good work on building something that scales so well. Can't wait to try Pipelining.

[drbrain]

Does heroku ps show anything useful? (I don't know much about heroku, so there may not be enough information there)

Can you compare logs between client and server with heroku log

… if you're actually killing the server on one connection, I think pipelining is just going to kill it faster ☺

[drbrain]

Also, if you're using mechanize, you should probably disable history with agent.max_history = 0. The latest release of mechanize only stores the latest 50 pages, but earlier versions store unlimited pages which will consume lots of memory.

[softwaregravy]

nothing useful RE CPU or anything else comes off heroku. They're a PAAS, so you're not supposed to be able to look under the hood.

Server won't die with this load. It's doing 100's of requests per second. The bottleneck is definitely on the Ruby side (or networking somehow). The volume of this thread is not significant to the load on the server.

Not using mechanize. All API's

[drbrain]

I ran 2,000,000 requests using this script through apache on localhost retrieving a static page. Apache was configured to keep the persistent connection open forever:

require 'pp'
require 'net/http/persistent'

uri = URI.parse 'http://localhost/'

http = Net::HTTP::Persistent.new

pp GC.stat

1_000_000.times do
  http.request uri
end

pp GC.stat

1_000_000.times do
  http.request uri
end

pp GC.stat

The GC stats were (before, mid, after):

{:count=>11,
 :heap_used=>77,
 :heap_length=>77,
 :heap_increment=>0,
 :heap_live_num=>21434,
 :heap_free_num=>9821,
 :heap_final_num=>22}

{:count=>57088,
 :heap_used=>77,
 :heap_length=>77,
 :heap_increment=>0,
 :heap_live_num=>20742,
 :heap_free_num=>10617,
 :heap_final_num=>0}

{:count=>116494,
 :heap_used=>77,
 :heap_length=>77,
 :heap_increment=>0,
 :heap_live_num=>20741,
 :heap_free_num=>10618,
 :heap_final_num=>0}

So there were 2318 extra GC runs in the second million requests, but no growth in the number of objects ruby was holding on to, and no growth in memory as reported by Activity Monitory.

I also ran with this patch to net/http/persistent.rb:

diff --git a/lib/net/http/persistent.rb b/lib/net/http/persistent.rb
index a154f98..c9f7e3e 100644
--- a/lib/net/http/persistent.rb
+++ b/lib/net/http/persistent.rb
@@ -789,7 +789,8 @@ class Net::HTTP::Persistent
     connection_id = connection.object_id

     begin
-      Thread.current[@request_key][connection_id] += 1
+      num = Thread.current[@request_key][connection_id] += 1
+      warn "#{num}\t#{connection_id}\t#{Time.now.to_i}" if num % 1_000 == 0
       response = connection.request req, &block

       if connection_close?(req) or

I then ran linear regression on the data and the linear fit line was y = 0.0009x + 1.332E+9 with R-squared of 1.0127, so it seems that your slowdown is either above Net::HTTP::Persistent or on the server side, unless you can think of some better tests for me to run.

(On my laptop, 2,000,000 requests took 1,729 seconds, or 1,157 requests/second. ab -n 100000 -k http://localhost reports 4923 requests/second, a ~4x speedup)

[drbrain]

Also, a scatter plot of the line (2000 data points) appeared linear in Numbers.