puma cluster 100% cpu usage

[cryo28]

Puma 2.0.0.b4 is run as rails app backend server by the means of upstart as:

bundle exec puma -C config/puma.rb -e staging >> log/puma.log 2>&1

If there are no workers 1 line in the config file puma uses cpu quite ordinary (less than 1% if there is not load. No problem for now).

As soon as I add workers 1 (or any higher number) to the puma's config file (effectively enabling puma cluster mode), puma master process consumes 100% CPU (under no load). The rails app is perfectly operatable at the same time. Don't know what will happend under high load though. The puma's stdout and stderr report no errors of any kind:

[25912] Puma 2.0.0.b4 starting in cluster mode... [25912] * Process workers: 1 [25912] * Min threads: 1, max threads: 16 [25912] * Environment: staging [25912] * Listening on unix:///srv/projects/projectname/current/tmp/sockets/puma.sock [25912] Use Ctrl-C to stop

[evanphx]

Can you post your config/puma.rb? Also, when you see a high CPU load, figure out which process is causing it. The workers have a different name (and likely the higher pid numbers). I need to know if it's the master or a worker (or multiple workers).

[cryo28]

Sure

require 'pathname'

APP_PATH  = Pathname.new('/srv/projects/come2me')
CURRENT   = APP_PATH.join('current')
SHARED    = APP_PATH.join('shared')
socket    = "unix://" + CURRENT.join('tmp/sockets/puma.sock').to_s

# See Puma::Configuration::DSL
bind        socket
pidfile     SHARED.join("pids/puma.pid")
threads     1, 16
state_path  SHARED.join('pids/puma.state')
#workers 4    # --- uncommenting this causes 100% cpu usage
directory   CURRENT
rackup "config.ru"

And this is the output of htop pointed at the upstart script running puma server. Please note 100% cpu is eaten by the master puma process, not the individual workers which are idle.

[masterkain]

Same:

[cryo28]

If this helps, strace and ltrace outputs are as follows: https://gist.github.com/4396552

[evanphx]

What version of ruby are you using?

[cryo28]

@evanphx 1.9.3-p125

[cryo28]

@evanphx It looks like the problem is somewhere around this code in Puma::CLi#run_cluster:

while !stop
  begin
     IO.select([read], nil, nil, 5)
     check_workers
  rescue Interrupt
     stop = true
  end
end

When puma cluster starts some of the child processes sends "!" on SIGCHLD signal to read IO. So IO.select immediately returns something like

 [[#<IO:fd 6>], [], []]

However, this "!" is never read from the IO:fd6 stream, and 5-second timeout to IO.select becomes worthless as read stream contains this unread "!" character and the code above runs infinite loop eating up 100% CPU.

Changing to the following code seems to have done the trick for me. However, I am uncertain whether this doesn't break child-master signaling and hot restarts.

while !stop
  begin
    result = IO.select([read], nil, nil, 5)
    log result.flatten.first.read_nonblock(255) if result
    check_workers
  rescue Interrupt
    stop = true
  end
end

[Wijnand]

Hi @cryo28,

did you already find out if this breaks signaling or hot restarts?

[cryo28]

@Wijnand Not yet. I returned to non-clustered mode for the time being.

[ozzyaaron]

I'm hitting this problem with the latest Puma (2.11.3) in development after I have used the debugger. There is an issue in byebug that seems to be getting worked on deivid-rodriguez/byebug#144