[PATCH] Add worker interrogation via INFO signals

[PATCH] Add worker interrogation via INFO signals

[Joel Watson]

Hey all,

Below is a proposed patch I worked on over the weekend. Just adding a note here to mention that I'm currently not a subscriber to the mailing list, so please CC me on any replies. Let me know what you all think. This change was made on a local topic branch off of the maint branch. If you'd like to view the change on GitHub, you can do so here: http://github.com/watsonian/unicorn/compare/maint...siginfo

-Joel
================================
>From a0ccb9efe508d4bd0a2a238305fedcbfc051d202 Mon Sep 17 00:00:00 2001
From: watsonian <watsonian@gmail.com>
Date: Mon, 26 Apr 2010 18:25:02 -0700
Subject: [PATCH] Add worker interrogation via INFO signals

You can now send a worker an INFO signal and it will write the
current request uri it's processing and how long it's been processing
it for to the log. Sending the master process an INFO signal will
send all workers an INFO signal as well.

This addresses cases where it's desirable to know exactly what a
worker is doing at a particular point in time (e.g., if it's hanging
on a particular request such that it isn't writing out to log files).
---
 lib/unicorn.rb |   25 ++++++++++++++++++++-----
 1 files changed, 20 insertions(+), 5 deletions(-)

diff --git a/lib/unicorn.rb b/lib/unicorn.rb
index b63abeb..b11360c 100644
--- a/lib/unicorn.rb
+++ b/lib/unicorn.rb
@@ -163,7 +163,7 @@ module Unicorn
     # releases of Unicorn.  You may need to access it in the
     # before_fork/after_fork hooks.  See the Unicorn::Configurator RDoc
     # for examples.
-    class Worker < Struct.new(:nr, :tmp, :switched)
+    class Worker < Struct.new(:nr, :tmp, :switched, :request_uri, :request_start)
 
       # worker objects may be compared to just plain numbers
       def ==(other_nr)
@@ -422,6 +422,8 @@ module Unicorn
             self.worker_processes += 1
           when :TTOU
             self.worker_processes -= 1 if self.worker_processes > 0
+          when :INFO
+            kill_each_worker(:INFO)
           when :HUP
             respawn = true
             if config.config_file
@@ -462,7 +464,7 @@ module Unicorn
 
     # list of signals we care about and trap in master.
     QUEUE_SIGS = [ :WINCH, :QUIT, :INT, :TERM, :USR1, :USR2, :HUP,
-                   :TTIN, :TTOU ]
+                   :TTIN, :TTOU, :INFO ]
 
     # defer a signal for later processing in #join (master process)
     def trap_deferred(signal)
@@ -629,9 +631,12 @@ module Unicorn
 
     # once a client is accepted, it is processed in its entirety here
     # in 3 easy steps: read request, call app, write app response
-    def process_client(client)
+    def process_client(client, worker)
       client.fcntl(Fcntl::F_SETFD, Fcntl::FD_CLOEXEC)
-      response = app.call(env = REQUEST.read(client))
+      env = REQUEST.read(client)
+      worker.request_start = Time.now.to_i
+      worker.request_uri = env["REQUEST_URI"]
+      response = app.call(env)
 
       if 100 == response.first.to_i
         client.write(Const::EXPECT_100_RESPONSE)
@@ -641,6 +646,9 @@ module Unicorn
       HttpResponse.write(client, response, HttpRequest::PARSER.headers?)
     rescue => e
       handle_error(client, e)
+    ensure
+      worker.request_start = Time.now.to_i
+      worker.request_uri = nil
     end
 
     # gets rid of stuff the worker has no business keeping track of
@@ -662,6 +670,7 @@ module Unicorn
       worker.user(*user) if user.kind_of?(Array) && ! worker.switched
       self.timeout /= 2.0 # halve it for select()
       build_app! unless preload_app
+      worker.request_start = Time.now.to_i # keep track of initial idle time
     end
 
     def reopen_worker_logs(worker_nr)
@@ -684,6 +693,7 @@ module Unicorn
       # closing anything we IO.select on will raise EBADF
       trap(:USR1) { nr = -65536; SELF_PIPE.first.close rescue nil }
       trap(:QUIT) { alive = nil; LISTENERS.each { |s| s.close rescue nil } }
+      trap(:INFO) { logger.info worker_info(worker) }
       [:TERM, :INT].each { |sig| trap(sig) { exit!(0) } } # instant shutdown
       logger.info "worker=#{worker.nr} ready"
       m = 0
@@ -704,7 +714,7 @@ module Unicorn
 
         ready.each do |sock|
           begin
-            process_client(sock.accept_nonblock)
+            process_client(sock.accept_nonblock, worker)
             nr += 1
             alive.chmod(m = 0 == m ? 1 : 0)
           rescue Errno::EAGAIN, Errno::ECONNABORTED
@@ -817,6 +827,11 @@ module Unicorn
             ]).concat(START_CTX[:argv]).join(' ')
     end
 
+    # used to see what a worker is doing when it's sent an :INFO signal
+    def worker_info(worker)
+      "worker[#{worker.nr}] - #{worker.request_uri || "idle"} - #{(Time.now.to_i - worker.request_start).to_s if worker.request_start}"
+    end
+
     def redirect_io(io, path)
       File.open(path, 'ab') { |fp| io.reopen(fp) } if path
       io.sync = true
-- 
1.7.0.2


_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: [PATCH] Add worker interrogation via INFO signals

[Eric Wong]

Joel Watson <joel@watsonian.net> wrote:
> Hey all,
> 
> Below is a proposed patch I worked on over the weekend. Just adding a
> note here to mention that I'm currently not a subscriber to the
> mailing list, so please CC me on any replies. Let me know what you all
> think. This change was made on a local topic branch off of the maint
> branch. If you'd like to view the change on GitHub, you can do so
> here: http://github.com/watsonian/unicorn/compare/maint...siginfo
> 
> -Joel
> ================================
> >From a0ccb9efe508d4bd0a2a238305fedcbfc051d202 Mon Sep 17 00:00:00 2001
> From: watsonian <watsonian@gmail.com>
> Date: Mon, 26 Apr 2010 18:25:02 -0700
> Subject: [PATCH] Add worker interrogation via INFO signals
> 
> You can now send a worker an INFO signal and it will write the
> current request uri it's processing and how long it's been processing
> it for to the log. Sending the master process an INFO signal will
> send all workers an INFO signal as well.
> 
> This addresses cases where it's desirable to know exactly what a
> worker is doing at a particular point in time (e.g., if it's hanging
> on a particular request such that it isn't writing out to log files).
> ---
>  lib/unicorn.rb |   25 ++++++++++++++++++++-----
>  1 files changed, 20 insertions(+), 5 deletions(-)

Hi Joel,

I'm alright with most of the changes, but I'm not ready to put more
things into every single request that people cannot opt-out of.

Since this data is written in a way that most users will rarely access,
I would avoid the changes to process_client:

>      # once a client is accepted, it is processed in its entirety here
>      # in 3 easy steps: read request, call app, write app response
> -    def process_client(client)
> +    def process_client(client, worker)
>        client.fcntl(Fcntl::F_SETFD, Fcntl::FD_CLOEXEC)
> -      response = app.call(env = REQUEST.read(client))
> +      env = REQUEST.read(client)
> +      worker.request_start = Time.now.to_i
> +      worker.request_uri = env["REQUEST_URI"]
> +      response = app.call(env)

And instead do it as middleware which requires opting in:

  # XXX Totally untested code written at ~1:30 AM, may not even compile
  # this middleware is only useful for Unicorn
  module Unicorn
  class Info < Struct.new(:app, :body)
    TIME_KEY = "unicorn.info_time".freeze

    # +env+ passed is always Unicorn::HttpRequest::REQ when used with Unicorn
    def call(env)
      env[TIME_KEY] = Time.now.to_i
      status, headers, self.body = app.call(env)
    end

    # this is a no-op proxy method, we only have this so we can
    # wrap the "close" method later on...
    def each(&block)
      body.each(&block)
    end

    # http_response.rb will call this in an ensure statement,
    # we'll finalize our per-request data here
    def close
      # Unicorn has only a single env hash to pass to Rack that always
      # gets reused across requests, this micro-optimization makes it
      # less likely to require expensive rehashing/resizing every
      # request.  Normally Unicorn will wait until the start of the next
      # request to clear this.
      HttpRequest::REQ.clear[TIME_KEY] = Time.now.to_i

      body.close if body.respond_to?(:close)
    end
  end # class Info
  end # module Unicorn

>        if 100 == response.first.to_i
>          client.write(Const::EXPECT_100_RESPONSE)
> @@ -641,6 +646,9 @@ module Unicorn
>        HttpResponse.write(client, response, HttpRequest::PARSER.headers?)
>      rescue => e
>        handle_error(client, e)
> +    ensure
> +      worker.request_start = Time.now.to_i
> +      worker.request_uri = nil
>      end


> +    # used to see what a worker is doing when it's sent an :INFO signal
> +    def worker_info(worker)
> +      "worker[#{worker.nr}] - #{worker.request_uri || "idle"} - #{(Time.now.to_i - worker.request_start).to_s if worker.request_start}"

No long lines, please, I can only work in 80 column terminals.

Also, the prevalent logger calls use "worker=#{worker.nr}" and not
"worker[#{worker.nr}]"

Since Unicorn::HttpRequest::REQ is global (ZOI rule), we can just read
that hash directly, no need to stash stuff in the worker object.
Based on the proposed middleware, we can have this.

     trap(:INFO) do
       t0 = HttpRequest::REQ[Info::TIME_KEY]
       logger.info "worker=#{worker.nr} - " \
                   "#{HttpRequest::REQ['REQUEST_URI'] || 'idle'} - " \
                   "#{(Time.now.to_i - t0) if t0}"
     end if defined?(Unicorn::Info)

Thanks for digging into the code, let me know what you think of the
proposed middleware solution.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: [PATCH] Add worker interrogation via INFO signals

[Eric Wong]

Hey Joel, did you get my original reply?

http://mid.gmane.org/20100427085922.GA8080@dcvr.yhbt.net

(putting you in the To: header in case your mail server doesn't like Cc:)

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: [PATCH] Add worker interrogation via INFO signals

[Joel Watson]

Yep, I got your original reply. I've been really busy since my initial post and haven't had much time to take a close look at your proposed middleware. I agree with you on it being unnecessary overhead for every request considering it won't be used all that often, so being able to include it as a middleware when needed seems like a great solution. Once I get some free time I'll take a closer look at your reply and give a more in-depth response. Thanks for taking the time to look over my patch and write up your proposed change as well!

-Joel

On May 6, 2010, at 2:19 PM, Eric Wong wrote:

> Hey Joel, did you get my original reply?
> 
> http://mid.gmane.org/20100427085922.GA8080@dcvr.yhbt.net
> 
> (putting you in the To: header in case your mail server doesn't like Cc:)
> 
> -- 
> Eric Wong

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying