2014-01-18

If you are working with highly intensive Unicorn deployments, you will be familiar with following problems.

How to find out what Ruby processes are doing?

Occasionally some Ruby processes are running pedal to the metal, possibly burning CPU like crazy, you know they shouldn't be, and you just can't tell what's happening. They are getting stuck, but can't tell where or why - it's frustrating.

Tracing sometimes works. Run strace -s 999 -fp <pid> on a suspicious process, and you may see some useful output. It may end with something like this, without any movement:

[pid  7990] select(18, [16 17], NULL, [7 8], {133, 947558} <unfinished ...>
[pid 17728] select(19, [14 18], NULL, [7 8], {22, 500000} <unfinished ...>

It's selecting something from file descriptor 19, and you can try to find out what it is:

$ lsof -p 17728
COMMAND   PID    USER   FD   TYPE             DEVICE SIZE/OFF      NODE NAME
...
ruby    17728    ruby   19u  IPv4          808319634      0t0       TCP web1.infra.net:35682->db3.infra.net:mysql (ESTABLISHED)

In this case it's waiting for MySQL, so you can look at what's happening over there. But sometimes you see that worker is hanging on select from a pipe or socket:

$ lsof -p 17728
COMMAND   PID    USER   FD   TYPE             DEVICE SIZE/OFF      NODE NAME
...
ruby    58610    ruby   12r  FIFO        0,8        0t0 3435272094 pipe
ruby    58610    ruby   13u  sock        0,6        0t0 3435234779 can't identify protocol
ruby    58610    ruby   14w  FIFO        0,8        0t0 3435270598 pipe

If your FD shows a pipe or socket, it's difficult to dig further.

Another case is when Ruby process is endlessly spilling it's guts into trace output, and you can see a pattern repeating, meaning that there is some sort of infinite loop going on, but it's hard to tell where.

There are more advanced techniques, but they are pretty cumbersome, and you may get your process killed before you manage to find out anything useful.

What Ruby is doing at any given moment?

Wouldn't it be nice if you could be able to find out what line of code your Ruby process is executing at any given moment? Good news is that you can. Combine Signal.trap with Thread.list and Thread#backtrace, and you're set.

Signal.trap('USR2') do
  pid = Process.pid 
  puts "[#{pid}] Received USR2 at #{Time.now}. Dumping threads:"
  Thread.list.each do |t|
    trace = t.backtrace.join("\n[#{pid}] ")
    puts "[#{pid}] #{trace}"
    puts "[#{pid}] ---"
  end
  puts "[#{pid}] -------------------"
end

Place this code in Unicorn's after_fork, Resque after_fork, beginning of Rake tasks, or wherever it fits. When something is stuck or otherwise suspicious, find the pid, and then do:

$ kill -USR2 26749

Take a look at unicorn log. It should show something like this:

[26749] Received USR2 at 2014-01-19 04:28:35 +0000. Dumping threads:
[26749] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:291:in `backtrace'
[26749] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:291:in `block (3 levels) in reload'
[26749] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:290:in `each'
[26749] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:290:in `block (2 levels) in reload'
[26749] /srv/app.intra.net/releases/20140118185816/app/controllers/welcome_controller.rb:8:in `call'
[26749] /srv/app.intra.net/releases/20140118185816/app/controllers/welcome_controller.rb:8:in `sleep'
[26749] /srv/app.intra.net/releases/20140118185816/app/controllers/welcome_controller.rb:8:in `index'
[26749] /usr/local/lib/ruby/gems/2.0.0/gems/actionpack-3.2.16/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
[26749] /usr/local/lib/ruby/gems/2.0.0/gems/actionpack-3.2.16/lib/abstract_controller/base.rb:167:in `process_action'
[26749] 
...
[26749] ---
[26749] -------------------

You can see that it's hanging on sleep in welcome_controller.rb, line 8. Bullseye.

Dumping Ruby threads when killing lazy Unicorn workers

You can't sit all day and watch those processes manually. Unicorn has a timeout configuration option, where it kills workers that run longer than given amount of seconds.

Trouble is that Unicorn sends SIGKILL when terminating stuck workers, and SIGKILL cannot be trapped. Workers get killed, and all you get are these lousy messages:

E, [2013-11-19T12:30:08.905908 #61893] ERROR -- : worker=75 PID:62991 timeout (46s > 45s), killing
E, [2013-11-19T12:30:08.939120 #61893] ERROR -- : reaped #<Process::Status: pid 62991 SIGKILL (signal 9)> worker=75

That's not very helpful. It just tells us that something went wrong, and that the perpetrator got a bullet in the head.

But we can patch things up by overriding Unicorn::HttpServer#murder_lazy_workers. Here's a monkey patch that will send SIGTERM 2 seconds before sending SIGKILL:

class Unicorn::HttpServer
  # forcibly terminate all workers that haven't checked in in timeout seconds.
  # The timeout is implemented using an unlinked File
  def murder_lazy_workers
    next_sleep = @timeout - 1
    now = Time.now.to_i
    WORKERS.dup.each_pair do |wpid, worker|
      tick = worker.tick
      0 == tick and next # skip workers that haven't processed any clients
      diff = now - tick
      tmp = @timeout - diff

      # monkey patch begins here
      if tmp < 2
        logger.error "worker=#{worker.nr} PID:#{wpid} running too long " \
                     "(#{diff}s), sending TERM"
        kill_worker(:TERM, wpid)
      end
      # end of monkey patch

      if tmp >= 0
        next_sleep > tmp and next_sleep = tmp
        next
      end
      next_sleep = 0
      logger.error "worker=#{worker.nr} PID:#{wpid} timeout " \
                   "(#{diff}s > [email protected]}s), killing"
      kill_worker(:KILL, wpid) # take no prisoners for timeout violations
    end
    next_sleep <= 0 ? 1 : next_sleep
  end
end

Place this code somewhere where it gets loaded on unicorn startup. It can be next to Unicorn's before_fork. You may want to adjust your Signal.trap to be a little more universal:

['TERM', 'USR2'].each do |sig|
  Signal.trap(sig) do
    pid = Process.pid 
    puts "[#{pid}] Received #{sig} at #{Time.now}. Dumping threads:"
    Thread.list.each do |t|
      trace = t.backtrace.join("\n[#{pid}] ")
      puts "[#{pid}] #{trace}"
      puts "[#{pid}] ---"
    end
    puts "[#{pid}] -------------------"
    exit unless sig == 'USR2'
  end
end

Restart your unicorns (this change may require full stop and clean start) and wait for any worker to receive a timeout. When it does, read your logs and rejoice:

E, [2014-01-19T04:17:19.340983 #26722] ERROR -- : worker=5 PID:27033 running too long (45s), sending TERM
[27033] Received USR2 at 2014-01-19 04:17:19 +0000. Dumping threads:
[27033] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:291:in `backtrace'
[27033] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:291:in `block (3 levels) in reload'
[27033] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:290:in `each'
[27033] /srv/app.intra.net/releases/shared/config/unicorn-config.rb:290:in `block (2 levels) in reload'
[27033] ... your code ...

And you can still use kill -USR2 <pid> on your unicorn workers (or any other Ruby process for that matter) to get the backtrace on demand. Just don't send USR2 to unicorn master process expecting to get a thread dump, it will reload your application instead.

Everything is so much simpler when you can pinpoint problems in your code.

Ruby
comments powered by Disqus All posts