Francois Simond
2006-Jun-15 14:49 UTC
[Mongrel] Performance leak with concurrent requests on static files (Rails)
Hi, I just found something weird for mongrel with static files. Performance endlessly decreases if mongrel serve static files from simultaneous requests : Here is the test setup: Ruby on Rails Mongrel (tested with 1.3.12.4 and 1.3.13-pre installed today) Ubuntu dapper, compiled ruby 1.8.4. http client : while true; do ab -n 1000 -c 30 http://localhost:3000/ 2>/dev/null | grep quest.*mean ; echo -- ; done Requests per second: 276.85 [#/sec] (mean) Time per request: 108.362 [ms] (mean) Time per request: 3.612 [ms] (mean, across all concurrent requests) -- Requests per second: 276.91 [#/sec] (mean) Time per request: 108.340 [ms] (mean) Time per request: 3.611 [ms] (mean, across all concurrent requests) -- Requests per second: 146.76 [#/sec] (mean) Time per request: 204.419 [ms] (mean) Time per request: 6.814 [ms] (mean, across all concurrent requests) -- Requests per second: 84.16 [#/sec] (mean) Time per request: 356.448 [ms] (mean) Time per request: 11.882 [ms] (mean, across all concurrent requests) -- Requests per second: 52.18 [#/sec] (mean) Time per request: 574.902 [ms] (mean) Time per request: 19.163 [ms] (mean, across all concurrent requests) -- Requests per second: 34.79 [#/sec] (mean) Time per request: 862.400 [ms] (mean) Time per request: 28.747 [ms] (mean, across all concurrent requests) -- Requests per second: 24.75 [#/sec] (mean) Time per request: 1212.168 [ms] (mean) Time per request: 40.406 [ms] (mean, across all concurrent requests) -- Requests per second: 18.40 [#/sec] (mean) Time per request: 1630.574 [ms] (mean) Time per request: 54.352 [ms] (mean, across all concurrent requests) -- Requests per second: 14.05 [#/sec] (mean) Time per request: 2135.263 [ms] (mean) Time per request: 71.175 [ms] (mean, across all concurrent requests) -- Requests per second: 10.79 [#/sec] (mean) Time per request: 2779.148 [ms] (mean) Time per request: 92.638 [ms] (mean, across all concurrent requests) lsof tool give indications about what happened : $ lsof -p 32200 COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME mongrel_r 32200 curio cwd DIR 8,3 4096 67168034 /home/curio/truc mongrel_r 32200 curio rtd DIR 8,3 4096 128 / mongrel_r 32200 curio txt REG 8,3 782262 671306909 /usr/local/bin/ruby mongrel_r 32200 curio mem REG 0,0 0 [heap] (stat: No such file or directory) mongrel_r 32200 curio mem REG 8,3 18707 134491718 /usr/local/lib/ruby/1.8/i686-linux/iconv.so mongrel_r 32200 curio mem REG 8,3 16101 335612184 /usr/local/lib/ruby/1.8/i686-linux/racc/cparse.so mongrel_r 32200 curio mem REG 8,3 159997 134491721 /usr/local/lib/ruby/1.8/i686-linux/nkf.so mongrel_r 32200 curio mem REG 8,3 10796 134491709 /usr/local/lib/ruby/1.8/i686-linux/digest.so mongrel_r 32200 curio mem REG 8,3 10754 201362293 /usr/local/lib/ruby/1.8/i686-linux/digest/md5.so mongrel_r 32200 curio mem REG 8,3 6780 134491717 /usr/local/lib/ruby/1.8/i686-linux/fcntl.so mongrel_r 32200 curio mem REG 8,3 20689 134491735 /usr/local/lib/ruby/1.8/i686-linux/strscan.so mongrel_r 32200 curio mem REG 8,3 77368 671116608 /usr/lib/libz.so.1.2.3 mongrel_r 32200 curio mem REG 8,3 12261 134491716 /usr/local/lib/ruby/1.8/i686-linux/etc.so mongrel_r 32200 curio mem REG 8,3 42358 134491740 /usr/local/lib/ruby/1.8/i686-linux/zlib.so mongrel_r 32200 curio mem REG 8,3 30975 537298194 /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13/lib/http11.so mongrel_r 32200 curio mem REG 8,3 45420 134491732 /usr/local/lib/ruby/1.8/i686-linux/socket.so mongrel_r 32200 curio mem REG 8,3 126144 134491736 /usr/local/lib/ruby/1.8/i686-linux/syck.so mongrel_r 32200 curio mem REG 8,3 1232784 671088799 /lib/tls/i686/cmov/libc-2.3.6.so mongrel_r 32200 curio mem REG 8,3 136368 671088803 /lib/tls/i686/cmov/libm-2.3.6.so mongrel_r 32200 curio mem REG 8,3 18900 671088801 /lib/tls/i686/cmov/libcrypt-2.3.6.so mongrel_r 32200 curio mem REG 8,3 8204 671088802 /lib/tls/i686/cmov/libdl-2.3.6.so mongrel_r 32200 curio mem REG 8,3 22108 134491734 /usr/local/lib/ruby/1.8/i686-linux/stringio.so mongrel_r 32200 curio mem REG 8,3 86404 469763148 /lib/ld-2.3.6.so mongrel_r 32200 curio 0r CHR 1,3 875 /dev/null mongrel_r 32200 curio 1w REG 8,3 2502854 101379 /home/curio/truc/log/mongrel.log mongrel_r 32200 curio 2w REG 8,3 2502854 101379 /home/curio/truc/log/mongrel.log mongrel_r 32200 curio 3u sock 0,4 3232114 can''t identify protocol mongrel_r 32200 curio 4w REG 8,3 90682401 17288 /home/curio/truc/log/production.log mongrel_r 32200 curio 5u sock 0,4 3234156 can''t identify protocol mongrel_r 32200 curio 6u sock 0,4 3234188 can''t identify protocol mongrel_r 32200 curio 7u sock 0,4 3234189 can''t identify protocol mongrel_r 32200 curio 8u sock 0,4 3234190 can''t identify protocol - cut - mongrel_r 32200 curio 205u sock 0,4 3246825 can''t identify protocol mongrel_r 32200 curio 206u sock 0,4 3246826 can''t identify protocol mongrel_r 32200 curio 207u sock 0,4 3246827 can''t identify protocol mongrel_r 32200 curio 208u sock 0,4 3248760 can''t identify protocol This problem always appears when concurrency level is > 1 and is amplified by concurrency level. Thanks ! -- Fran?ois Simond
Zed Shaw
2006-Jun-15 16:22 UTC
[Mongrel] Performance leak with concurrent requests on static files (Rails)
On Thu, 2006-06-15 at 16:49 +0200, Francois Simond wrote:> Hi, > > I just found something weird for mongrel with static files. > Performance endlessly decreases if mongrel serve static files from > simultaneous requests : > > Here is the test setup: > Ruby on Rails > Mongrel (tested with 1.3.12.4 and 1.3.13-pre installed today) > Ubuntu dapper, compiled ruby 1.8.4. > > http client : > > while true; do ab -n 1000 -c 30 http://localhost:3000/ 2>/dev/null | > grep quest.*mean ; echo -- ; doneFantastic. You may have found the slow socket leak I couldn''t replicate, all thanks to ab''s horribly implemented client protocol (you''d think guys who wrote the most popular web server could write a well behaved testing tool). ab basically makes a ton of connections when concurrency > 1, and then when it runs out of time it just closes the connection causing an EPIPE on the socket. Mongrel seems to not be closing the socket when this happens--which I have to investigate. The slowdown you''re seeing comes from sockets that never close slowly filling up the 1024 available sockets for the internal select call. As this fills up Mongrel gets less and less space to deal with connections until it finally dies. Thanks for tracking this down, I''ll have it fixed today. -- Zed A. Shaw http://www.zedshaw.com/ http://mongrel.rubyforge.org/