Hypermail

From: Timothy Garnett <tgarnett#panjiva.com>
Date: Mon, 12 Dec 2011 14:33:53 -0500

Hi all,

We've been using Haproxy for a couple of years now to load balance our external traffic and our internal backend services. We recently upgraded from version 1.4.8 to 1.4.18 and we noticed some connection initialization performance issues when connecting from Ruby's standard net::http library, specifically it takes about 200ms longer for the connection to establish then it used to. It's unclear if the issue comes from Ruby or Haproxy. We're interested if anyone has run into similar problems and if there are things we can do to help identify the issue for fixing.

For the example code below we have a tomcat server running on port 8888. Haproxy is listening on port 8887 and loadbalancing to it as the only non-backup server in that listen block. This is using ruby 1.9.1p378 (1.9.1p429 has same issue). Note that it doesn't matter if it's on localhost (as below) or another machine.

common
require 'net/http'
require 'benchmark'

(1) Connecting through Haproxy 1.4.18 to tomcat 10.times do
http = Net::HTTP.start(localhost, 8887) Benchmark.realtime do
http.post(path, URI.escape(params))
end
puts m
http.finish
end

0.283593893051147
0.291399002075195
0.286567211151123
0.291929006576538
0.292807579040527
0.292263031005859
0.292068481445312
0.29228663444519
0.284586191177368
0.307933330535889

=> 10

(2) The slowness is only in establishing the connection/first request http = Net::HTTP.start(localhost, 8887)
10.times do
Benchmark.realtime do
http.post(path, URI.escape(params))
end
puts m
end
http.finish

0.284791707992554
0.0461645126342773
0.0307860374450684
0.0891320705413818
0.0332472324371338
0.0640416145324707
0.0728485584259033
0.0676729679107666
0.0717344284057617
0.0906641483306885

=> 10

(3) If we bypass Haproxy and hit tomcat directly don't see the slowness 10.times do
http = Net::HTTP.start(localhost, 8888) Benchmark.realtime do
http.post(path, URI.escape(params))
end
puts m
http.finish
end

0.0538337230682373
0.0343561172485352
0.0473048686981201
0.039668083190918
0.0315456390380859
0.0296871662139893
0.0543346405029297
0.0314345359802246
0.0287115573883057
0.0359044075012207

=> 10

(4) If we hit Haproxy 1.4.8 (same haproxy config, minus stats socket) we don't see the slowness (or at least not nearly to the same degree) 10.times do
http = Net::HTTP.start(localhost, 8887) Benchmark.realtime do
http.post(path, URI.escape(params))
end
puts m
http.finish
end

0.0857374668121338
0.0475654602050781
0.0486986637115479
0.045814037322998
0.0468342304229736
0.053391695022583
0.0451278686523438
0.0491366386413574
0.053142786026001
0.0475285053253174

=> 10

(5) If we use wget/curl or go through nginx we don't see the slowness. time wget "http://localhost:8887/<http://localhost:8888/bridge/JSONControllerServlet.do?&M=recs_per_page:10%7Chost:localhost%7Cport:5519&N=0&Ntk=commodity_and_supplier_name_and_spp&Ntx=mode+matchboolean&Ntt=cow&Nr=OR(record_spec:c21633828,record_spec:c57722532,record_spec:c23517549,record_spec:c81817342,record_spec:c8158662,record_spec:c49196212,record_spec:c80879252,record_spec:c68471891,record_spec:c8993453,record_spec:c6351387)> ..."
=> real 0.035 seconds

(6) Oddly enough if the connection goes through an ssh tunnel we don't see the problem.
machine1> ssh -L 6789:localhost:8887 machine2 on machine 1
10.times do
http = Net::HTTP.start(localhost, 6789) Benchmark.realtime do
http.post(path, URI.escape(params))
end
puts m
http.finish
end

0.0445387363433838
0.0284795761108398
0.0327854156494141
0.0375099182128906
0.030207633972168
0.0273423194885254
0.0348851680755615
0.0450797080993652
0.0429427623748779
0.0306704044342041

=> 10

Some info on our haproxy config:

global

    maxconn 5000
    tune.bufsize 1048576
    tune.maxrewrite 524288

    log     127.0.0.1   local0
    log     127.0.0.1   local1 notice
    daemon
    nbproc      1
    user        haproxy
    group       haproxy
    chroot      ***

spread-checks 5
stats socket *** # only in 1.4.18 config, not in 1.4.8 config

defaults

    option      httplog
    balance     roundrobin
    mode        http

    timeout client 180000
    timeout server 180000
    timeout queue 30000
    timeout connect 5000
    retries 5
    option redispatch
    stats enable
    stats uri **********
    stats realm Haproxy\ Statistics
    stats auth *********
    stats refresh 20s
    monitor-uri *********
    option abortonclose
    option allbackups

listen **** :8887

    balance leastconn
    log 127.0.0.1 local1 notice
    server *** ***:8888 check port 8891 inter 3000 fall 1 rise 2     server *** ***:8888 check port 8892 inter 3000 fall 1 rise 2 backup # bunch of other listen blocks (~10, biggest has 140 server lines) ....
# one tcp listen block
listen *** :****

    mode tcp
    option tcplog
    retries 3
    timeout connect 2s
    timeout server 1s
    server *** ***:**** check inter 1000 fall 1 rise 2     server *** ***:**** check inter 1000 fall 1 rise 2 backup

Tim Received on 2011/12/12 20:33

Slowness in establishing connections from ruby to Haproxy after upgrading from 1.4.8 to 1.4.18