requests failing sometimes #274

mrbrdo · 2013-06-07T10:14:34Z

Hey,

I'm experiencing very slow requests, it seems especially if I don't access the server for a while, it feels similar to how Heroku works on the free version (like it has to start up the whole rails app first). After the first request goes through it works pretty fast (occasionally some hickups though).
Any idea? I'm using MRI with 3 workers and thread config 1:8

EDIT: I updated the description of the problem below... I am getting errors, like sometimes puma can't boot to serve the request.

PetrKaleta · 2013-06-10T09:28:08Z

This is not issue of Puma, Heroku free instances are automatically sleeping after some time of inactivity...

mrbrdo · 2013-06-10T10:08:47Z

Yes, but I'm not on Heroku. However I am having similar problems with Unicorn too (+ my workers are even dying on Unicorn), so maybe this is a problem with my app. Any idea what it could be?
PS: does it even make sense to use multiple threads per worker on MRI? how many?

PetrKaleta · 2013-06-10T10:37:44Z

Are you experiencing same issue with 8:8 configuration?

Btw: sorry for my previous response, I misunderstood your previous question.

mrbrdo · 2013-06-10T13:28:52Z

Let me get back to you at the end of the week, I'll do some testing. Thanks!

mrbrdo · 2013-06-17T22:35:30Z

Ok I am back on Puma. I still have this problem though. I think the 'slowness' coincides with this error in my puma error log:

2013-06-18 00:03:52 +0200: Read error: #<Errno::EPIPE: Broken pipe>
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `syswrite'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `fast_write'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:475:in `handle_request'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:243:in `process_client'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:142:in `block in run'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/thread_pool.rb:92:in `call'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/thread_pool.rb:92:in `block in spawn_thread'
2013-06-18 00:05:06 +0200: Read error: #<Errno::EPIPE: Broken pipe>
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `syswrite'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `fast_write'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:475:in `handle_request'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:243:in `process_client'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:142:in `block in run'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/thread_pool.rb:92:in `call'
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/thread_pool.rb:92:in `block in spawn_thread'

It seems when this happens the client has to wait a long time before he gets a response. I did try 8:8 thread config (and cluster of 8 workers also). I am on MRI 1.9.3-p429, nginx, running on VPS 32bit ubuntu with 2GB RAM, 1.4GB used. Would appreciate any speedy ideas as I'm running this in production so it's kinda awkward for me :) The above is the only problem I can see in my logs. I'm using puma master branch from about a week ago.
Thanks!

mrbrdo · 2013-06-18T09:17:12Z

@PetrKaleta some more info, it seems the EPIPE error in puma error log conincides a bit with errors from nginx log.

nginx:
2013/06/18 10:18:55 [error] 12597#0: *3670 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 81.139.159.67, server: test.x.com, request: "GET / HTTP/1.1", upstream: "http://unix:///x/web/shared/sockets/puma.sock:/", host: "users.x.com"
puma:
2013-06-18 10:19:34 +0200: Read error: #<Errno::EPIPE: Broken pipe>
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `syswrite'
nginx:
2013/06/18 10:23:46 [error] 12597#0: *3678 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 81.139.159.67, server: test.x.com, request: "GET / HTTP/1.1", upstream: "http://unix:///x/web/shared/sockets/puma.sock:/", host: "users.x.com"
puma:
2013-06-18 10:24:25 +0200: Read error: #<Errno::EPIPE: Broken pipe>
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `syswrite'

However it's not always the case... Sometimes nginx has this error instead:

nginx:
2013/06/18 03:55:40 [info] 12597#0: *2323 client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 71.177.224.171, server: test.x.com, request: "GET / HTTP/1.1", upstream: "http://unix:///x/web/shared/sockets/puma.sock:/", host: "users.x.com", referrer: "http://x.com/"
puma:
2013-06-18 03:55:49 +0200: Read error: #<Errno::EPIPE: Broken pipe>
/x/web/shared/bundle/ruby/1.9.1/bundler/gems/puma-bd97b6ec3e24/lib/puma/server.rb:613:in `syswrite'

I'm not sure if these are related, but that's all I could find. It seems like in some cases my worker can't start in time to serve the request (only my assumption!). I don't understand why it has to start anyway, since this is not happening after puma restart, it's happening on random requests when puma is already "hot". Is there any way I could find out if my workers are dying and why?

mrbrdo · 2013-06-18T09:29:22Z

Also I should update the title of the issue, the bigger problem for me is that sometimes I get an error page from nginx (I presume), basically the page loads for some time and then I get an error, probably 504 from nginx.

ukolovda · 2013-07-04T08:42:33Z

I have same problem too. It occured under high traffic.

tkoenig · 2013-07-04T08:51:23Z

I had the same problem on heroku.

Reverting to puma 2.0.1 fixed this currently for me.

evanphx · 2013-07-04T22:12:22Z

@tkoenig What version were you on?

mrbrdo · 2013-07-04T22:39:45Z

Master at the time. Maybe it could have been a low memory issue?

evanphx · 2013-07-04T22:41:06Z

@mrbrdo Does this still happen with 2.2.2?

mrbrdo · 2013-07-04T22:57:42Z

Not sure but I am not getting any reports about issues anymore... I did upgrade RAM on the server though. Im still on master I think

tkoenig · 2013-07-08T08:49:28Z

It happened to me with puma 2.1.1. I'm gonna try the latest version soon and report back if I still face this issue.

kenips · 2013-07-30T22:56:44Z

Still happening with Puma 2.4.0… any idea?

mrbrdo · 2013-07-31T10:54:50Z

For me it was too little RAM on a VPS I think. Do you have enough RAM?

ukolovda · 2013-07-31T11:43:22Z

Hello, I do not try it more, but server has enough RAM (dedicated server).

kenips · 2013-07-31T13:10:57Z

Still has 3GB in free - must be enough right?

kenips · 2013-08-28T19:05:26Z

@evanphx any more information that you need to fix this? At 2.5.1 now…

28-08-2013 14:53: Read error: #<Errno::EPIPE: Broken pipe>
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/server.rb:762:in `syswrite'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/server.rb:762:in `fast_write'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/server.rb:589:in `handle_request'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/server.rb:343:in `process_client'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/server.rb:242:in `block in run'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/thread_pool.rb:92:in `call'
/var/projects/twitter/vendor/bundle/ruby/2.0.0/gems/puma-2.5.1/lib/puma/thread_pool.rb:92:in `block in spawn_thread'

Edit: for those who ask about memory, 16GB total, 8GB used, 7GB free.

phlipper · 2013-08-29T01:05:02Z

I am seeing the same issue as @kenips on MRI 2.0.0-p247 and puma 2.5.1 whether I restart via pumactl or manually sending a kill -s USR1 to the pid using either unix or tcp sockets.

             total       used       free     shared    buffers     cached
Mem:          3750       1695       2054          0        245       1025
-/+ buffers/cache:        424       3326
Swap:            0          0          0

Edit: The same issue occurs with either 1 or 2 workers, and any thread count.

mrbrdo · 2013-08-29T19:47:19Z

I suggest to open a new issue since it's not the same problem, I was getting these errors seemingly randomly not when performing hot/cold restart. So it's not the same issue.

nmccready · 2013-09-06T20:28:48Z

This issue happens on Jruby-1.7.4 as well.

evanphx · 2013-09-09T16:55:33Z

If anyone is still seeing this, please open a new issue with backtrace and reproduction information.

nmccready · 2013-09-10T20:02:44Z

Is there a specific issue for this yet or a specific issue naming convention that should be defined? The logs that I have are posted on issue #360 . I'll see if I can get a deeper trace.

nmccready · 2013-09-10T21:16:42Z

This is all I have it repeats indefinitely for each client.

2013-09-10 17:11:25 -0400: Read error: #<Errno::EPIPE: Broken pipe - Broken pipe>
org/jruby/RubyIO.java:1294:in `syswrite'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:762:in `fast_write'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:589:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:470:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:343:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:339:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:242:in `run'
org/jruby/RubyProc.java:255:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/thread_pool.rb:92:in `spawn_thread'
2013-09-10 17:11:25 -0400: Rack app error: #<ThreadError: Mutex relocking by same thread>
org/jruby/ext/thread/Mutex.java:90:in `lock'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-1.4.5/lib/rack/lock.rb:14:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/actionpack-3.2.14/lib/action_dispatch/middleware/static.rb:63:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-cache-1.2/lib/rack/cache/context.rb:245:in `fetch'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/railties-3.2.14/lib/rails/engine.rb:484:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/railties-3.2.14/lib/rails/application.rb:231:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/newrelic_rpm-3.5.8.72/lib/new_relic/rack/developer_mode.rb:24:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/rack-1.4.5/lib/rack/deflater.rb:13:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/configuration.rb:68:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:472:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:470:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:343:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:339:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:242:in `run'
org/jruby/RubyProc.java:255:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/thread_pool.rb:92:in `spawn_thread'
2013-09-10 17:11:25 -0400: Read error: #<Errno::EPIPE: Broken pipe - Broken pipe>
org/jruby/RubyIO.java:1294:in `syswrite'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:762:in `fast_write'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:589:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:470:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:343:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:339:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:242:in `run'
org/jruby/RubyProc.java:255:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/thread_pool.rb:92:in `spawn_thread'
2013-09-10 17:11:25 -0400: Read error: #<Errno::EPIPE: Broken pipe - Broken pipe>
org/jruby/RubyIO.java:1294:in `syswrite'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:762:in `fast_write'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:589:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:470:in `handle_request'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:343:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:339:in `process_client'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/server.rb:242:in `run'
org/jruby/RubyProc.java:255:in `call'
/home/nem/.rvm/gems/jruby-1.7.4/gems/puma-2.5.1-java/lib/puma/thread_pool.rb:92:in `spawn_thread'

mrbrdo · 2013-09-10T21:22:04Z

Well the Read error: #<Errno::EPIPE: Broken pipe - Broken pipe> is definitely a problem since I am getting several of these every day too. I can't really say what it looks like on the client side when this happens since I am unsure if I have experienced it myself. I haven't gotten any reports of problems but it may be that users just retry if this happens. Even in case it is harmless I would argue it's still a bug since then it's not really an error that should be logged. So definitely something to look into.

nmccready · 2013-09-10T21:24:07Z

I just double checked to see if multiple instances of puma may be an issue. However locusio still DOS'es a single instance of puma after hitting it around 300-350RPS. Also the errors are the same.

nmccready · 2013-09-11T17:08:30Z

Pull / Fix #369

mrbrdo closed this as completed Jun 10, 2013

mrbrdo reopened this Jun 17, 2013

evanphx closed this as completed in e3d8744 Jul 6, 2013

nmccready mentioned this issue Sep 6, 2013

A really lowlevel plumbing error occured. Maytag(tm) error #360

Closed

mrbrdo mentioned this issue Sep 10, 2013

Read error: #<Errno::EPIPE: Broken pipe> #368

Closed

nmccready mentioned this issue Sep 11, 2013

Handle BrokenPipe, StandardError and IOError in fat_wrote and break out #369

Merged

dt1973 mentioned this issue Mar 25, 2015

Puma slow/failing on initial requests #678

Closed

MSP-Greg added a commit to MSP-Greg/puma that referenced this issue Aug 1, 2020

puma#19 puma#274

864ccc0

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

requests failing sometimes #274

requests failing sometimes #274

mrbrdo commented Jun 7, 2013

PetrKaleta commented Jun 10, 2013

mrbrdo commented Jun 10, 2013

PetrKaleta commented Jun 10, 2013

mrbrdo commented Jun 10, 2013

mrbrdo commented Jun 17, 2013

mrbrdo commented Jun 18, 2013

mrbrdo commented Jun 18, 2013

ukolovda commented Jul 4, 2013

tkoenig commented Jul 4, 2013

evanphx commented Jul 4, 2013

mrbrdo commented Jul 4, 2013

evanphx commented Jul 4, 2013

mrbrdo commented Jul 4, 2013

tkoenig commented Jul 8, 2013

kenips commented Jul 30, 2013

mrbrdo commented Jul 31, 2013

ukolovda commented Jul 31, 2013

kenips commented Jul 31, 2013

kenips commented Aug 28, 2013

phlipper commented Aug 29, 2013

mrbrdo commented Aug 29, 2013

nmccready commented Sep 6, 2013

evanphx commented Sep 9, 2013

nmccready commented Sep 10, 2013

nmccready commented Sep 10, 2013

mrbrdo commented Sep 10, 2013

nmccready commented Sep 10, 2013

nmccready commented Sep 11, 2013

requests failing sometimes #274

requests failing sometimes #274

Comments

mrbrdo commented Jun 7, 2013

PetrKaleta commented Jun 10, 2013

mrbrdo commented Jun 10, 2013

PetrKaleta commented Jun 10, 2013

mrbrdo commented Jun 10, 2013

mrbrdo commented Jun 17, 2013

mrbrdo commented Jun 18, 2013

mrbrdo commented Jun 18, 2013

ukolovda commented Jul 4, 2013

tkoenig commented Jul 4, 2013

evanphx commented Jul 4, 2013

mrbrdo commented Jul 4, 2013

evanphx commented Jul 4, 2013

mrbrdo commented Jul 4, 2013

tkoenig commented Jul 8, 2013

kenips commented Jul 30, 2013

mrbrdo commented Jul 31, 2013

ukolovda commented Jul 31, 2013

kenips commented Jul 31, 2013

kenips commented Aug 28, 2013

phlipper commented Aug 29, 2013

mrbrdo commented Aug 29, 2013

nmccready commented Sep 6, 2013

evanphx commented Sep 9, 2013

nmccready commented Sep 10, 2013

nmccready commented Sep 10, 2013

mrbrdo commented Sep 10, 2013

nmccready commented Sep 10, 2013

nmccready commented Sep 11, 2013