Skip to content

Re-use TCP connections across API calls#214

Merged
rohitpaulk merged 1 commit into
masterfrom
rohitpaulk/re-use-connections
Dec 17, 2019
Merged

Re-use TCP connections across API calls#214
rohitpaulk merged 1 commit into
masterfrom
rohitpaulk/re-use-connections

Conversation

@rohitpaulk

@rohitpaulk rohitpaulk commented Dec 6, 2019

Copy link
Copy Markdown
Collaborator

Fixes #148.

Summary of changes

  • Rename Analytics::Request -> Analytics::Transport
    • This object no longer represents one request, it supports sending multiple requests and a shutdown method. Transport seemed like a better name
  • Rename Transport#post -> Transport#send
    • A Transport object's interface doesn't have to be HTTP-aware, just send should do.
  • Add Tranport#shutdown to close persistent connections
  • Re-use Transport object in Analytics::Worker

For a commit-wise split of changes, see this diff.

Context

There was a previous failed attempt to fix this in #149. That had to be reverted because of #167. The error happened when many Analytics::Client objects were created, instead of a singleton client (a valid use-case, although uncommon).

I was able to trigger the error with this command:

sh -c "ulimit -n 7 && ruby debug.rb"

where debug.rb is this script:

require "segment/analytics"

5.times do
  puts "--- New client ---"
  client = Segment::Analytics.new(write_key: "abcd")
  300.times do
    client.track(event: "hey", user_id: 123)
  end

  client.flush
end

(ulimit -n <number> places a limit on how many files the process can keep open)

When I use the old PR (#149), this errors out:

[2019-12-06T13:02:36.186533 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:37.778800 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:02:37.785581 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:38.143361 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:02:38.148247 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:38.449847 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:02:38.508348 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:40.104691 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:02:40.107417 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:40.427505 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:02:40.431608 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:40.749493 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:02:40.824610 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:02:40.825664 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 10 retries left
D, [2019-12-06T13:02:40.961936 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 9 retries left
D, [2019-12-06T13:02:41.088871 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 8 retries left
D, [2019-12-06T13:02:41.391427 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 7 retries left
D, [2019-12-06T13:02:41.853409 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 6 retries left
D, [2019-12-06T13:02:42.359242 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 5 retries left
D, [2019-12-06T13:02:43.404450 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 4 retries left
D, [2019-12-06T13:02:44.313979 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 3 retries left
D, [2019-12-06T13:02:45.630458 #40332] DEBUG -- Segment::Analytics: [analytics-ruby] Retrying request, 2 retries left
E, [2019-12-06T13:02:49.057888 #40332] ERROR -- Segment::Analytics: [analytics-ruby] Failed to open TCP connection to api.segment.io:443 (Too many open files - getaddrinfo)
E, [2019-12-06T13:02:49.058009 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/net/http.rb:949:in `rescue in block in connect'
E, [2019-12-06T13:02:49.058079 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/net/http.rb:946:in `block in connect'
E, [2019-12-06T13:02:49.058134 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/timeout.rb:93:in `block in timeout'
E, [2019-12-06T13:02:49.058182 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/timeout.rb:103:in `timeout'
E, [2019-12-06T13:02:49.058231 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/net/http.rb:945:in `connect'
E, [2019-12-06T13:02:49.058277 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/net/http.rb:930:in `do_start'
E, [2019-12-06T13:02:49.058324 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/2.6.0/net/http.rb:925:in `start'
E, [2019-12-06T13:02:49.058371 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:123:in `send_request'
E, [2019-12-06T13:02:49.058416 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:44:in `block in post'
E, [2019-12-06T13:02:49.058460 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:89:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058504 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058620 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058657 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058690 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058723 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058755 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058788 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058820 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058852 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:99:in `retry_with_backoff'
E, [2019-12-06T13:02:49.058886 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/request.rb:43:in `post'
E, [2019-12-06T13:02:49.058917 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/worker.rb:45:in `run'
E, [2019-12-06T13:02:49.058950 #40332] ERROR -- Segment::Analytics: [analytics-ruby] /home/rohitpaulk/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/analytics-ruby-2.2.8.pre/lib/segment/analytics/client.rb:180:in `block (2 levels) in ensur
e_worker_running'                                                                                                                         

On master, this runs successfully but takes 24s:

--- New client ---
D, [2019-12-06T12:58:57.872369 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:58:59.430815 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:58:59.438885 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:00.980734 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:00.983564 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:02.485581 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T12:59:02.600570 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:04.272310 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:04.275740 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:05.867246 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:05.870147 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:07.390697 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T12:59:07.417606 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:08.942721 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:08.947912 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:10.462575 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:10.465352 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:12.102836 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T12:59:12.138678 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:13.781219 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:13.784866 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:15.283547 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:15.286827 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:16.825358 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T12:59:16.856068 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:18.481554 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:18.487062 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:20.038068 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T12:59:20.040625 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T12:59:21.611332 #39321] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
sh -c "ulimit -n 7 && ruby debug.rb"  0.39s user 0.07s system 1% cpu 24.022 total

Using the code in this PR, the script runs in 12s:

--- New client ---
D, [2019-12-06T13:03:40.619387 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:42.169345 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:42.171981 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:42.616038 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:42.617797 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:42.961990 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:03:43.050122 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:44.577005 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:44.579298 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:44.918715 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:44.924724 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:45.241328 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:03:45.273792 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:46.859305 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:46.864293 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:47.171529 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:47.174948 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:47.508773 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:03:47.590015 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:49.178970 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:49.181920 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:49.486275 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:49.487703 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:49.785491 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
--- New client ---
D, [2019-12-06T13:03:49.802279 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:51.422746 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:51.425518 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:51.740109 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
D, [2019-12-06T13:03:51.742786 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Sending request for 100 items
D, [2019-12-06T13:03:52.045620 #40696] DEBUG -- Segment::Analytics: [analytics-ruby] Response status code: 200
sh -c "ulimit -n 7 && ruby debug.rb"  0.50s user 0.09s system 4% cpu 11.910 total

- Rename Analytics::Request -> Analytics::Transport
- Rename Transport#post -> Transport#send
- Add Tranport#shutdown to close persistent connections
- Re-use Transport object in Analytics::Worker
@rohitpaulk rohitpaulk marked this pull request as ready for review December 6, 2019 07:44
@rohitpaulk rohitpaulk requested a review from lubird December 6, 2019 07:44
@rohitpaulk rohitpaulk merged commit b8b285e into master Dec 17, 2019
@rohitpaulk rohitpaulk deleted the rohitpaulk/re-use-connections branch December 17, 2019 03:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

TCP connections aren't reused across batches

2 participants