unicorn の hook が呼ばれるタイミングを調べてみた

Ruby unicorn

unicorn には特定のタイミングで発火する hook を仕掛ける仕組みがあるが、それらの hook が呼ばれるタイミングを正確にわかっていなかったのでメモ。 いちおう公式のドキュメントはこちらにある。ここで言及する unicorn のバージョンは v5.3.0。

それぞれの hook の説明

after_fork, after_worker_exit, after_worker_ready, before_exec, before_fork の 5 つある。 以下はそれぞれの説明&コードの場所。

after_fork

この hook は fork した後にワーカープロセスから呼ばれる ( init_worker_process )。 init_worker_process は fork したワーカープロセスの中で呼ばれる worker_loop で呼ばれるメソッド。

after_worker_exit

この hook はワーカープロセスが exit する際にマスタープロセスから呼ばれる。 ワーカーが死んだ後、ワーカーの socket などを閉じた後に呼ばれる ( reap_all_worker )。

after_worker_ready

この hook はワーカープロセスがレスポンスを受けられる状態になったところでワーカープロセスから呼ばれる。 fork したワーカープロセスの中で呼ばれる ( worker_loop )。

before_exec

この hook は新しい unicorn のコマンドを exec する直前にマスタプロセスによって呼ばれる。 unicorn は graceful restart などをする際に、呼び出されたときと同じコマンド (例えば unicorn -c unicorn.ru など) を Kernel#exec する。 その直前に呼ばれる ( reexec )。

before_fork

それぞれのワーカプロセスを fork する前にマスタープロセスから呼ばれる。 Unicorn::Worker オブジェクトを作成したらすぐ呼ばれている ( spawn_missing_workers )。

呼び出しタイミングの確認

ワーカーが 2 つの設定で幾つか実験を行って呼び出しタイミングを見てみた。今回確認する際に使用したソースコードは以下。 もちろんオプションによっては呼び出し順序が変わるので注意。

github.com

起動時

  1. before_fork
  2. after_fork
  3. after_worker_ready

マスタープロセスが起動してから 2 つのワーカーに対してそれぞれ before_fork, after_fork, affter_worker_ready が呼ばれている。 マスタープロセスの pid が 46056 でワーカープロセスがそれぞれ、46090 と 46089 になる。 before_fork はマスタープロセスからよばれるので pid は 46056 になる。それ以外はワーカープロセスで呼ばれるのでそれぞれの pid になる。

$ be unicorn -c unicorn.ru
I, [2017-05-21T16:26:53.009330 #46056]  INFO -- : listening on addr=0.0.0.0:8080 fd=9
I, [2017-05-21T16:26:53.009448 #46056]  INFO -- : [before_fork] worker=0 pid=46056
I, [2017-05-21T16:26:53.010518 #46056]  INFO -- : [before_fork] worker=1 pid=46056
I, [2017-05-21T16:26:53.012068 #46056]  INFO -- : master process ready
I, [2017-05-21T16:26:53.012010 #46089]  INFO -- : [after_fork] worker=0 pid=46089
I, [2017-05-21T16:26:53.012433 #46089]  INFO -- : Refreshing Gem list
I, [2017-05-21T16:26:53.013825 #46090]  INFO -- : [after_fork] worker=1 pid=46090
I, [2017-05-21T16:26:53.014232 #46090]  INFO -- : Refreshing Gem list
I, [2017-05-21T16:26:53.121563 #46090]  INFO -- : [after_worker_ready] worker=1 pid=46090
I, [2017-05-21T16:26:53.125676 #46089]  INFO -- : [after_worker_ready] worker=0 pid=46089

マスタープロセスに SIGINT

  1. after_worker_exit

すぐにワーカープロセスを殺して after_worker_exit が呼ばれ、その後マスタープロセスも死ぬ。 after_worker_exit はマスタープロセスで呼ばれるので pid は 46056 となる。

I, [2017-05-21T16:29:04.026190 #46056]  INFO -- : [after_worker_exit] worker=1 pid=46056 status=pid 46090 exit 0
I, [2017-05-21T16:29:04.026515 #46056]  INFO -- : [after_worker_exit] worker=0 pid=46056 status=pid 46089 exit 0
I, [2017-05-21T16:29:04.026615 #46056]  INFO -- : master complete

ワーカープロセスに SIGINT

  1. after_worker_exit
  2. before_fork
  3. after_fork
  4. after_worker_ready

kill -s INT 46651 を実行した後のログ。 マスタープロセスの pid は 46622 なので、after_worker_exit はマスタープロセス内で呼ばれていることがわかる。 そのあと、新しいワーカープロセスを作成するので起動時と同じログになる(ただしワーカーは 1 つ)。

I, [2017-05-21T16:35:10.707660 #46622]  INFO -- : [after_worker_exit] worker=1 pid=46622 status=pid 46651 exit 0
I, [2017-05-21T16:35:10.707795 #46622]  INFO -- : [before_fork] worker=1 pid=46622
I, [2017-05-21T16:35:10.709798 #46653]  INFO -- : [after_fork] worker=1 pid=46653
I, [2017-05-21T16:35:10.710304 #46653]  INFO -- : Refreshing Gem list
I, [2017-05-21T16:35:10.828349 #46653]  INFO -- : [after_worker_ready] worker=1 pid=46653

マスターに SIGUSER2 (graceful restart)

  1. before_exec
  2. before_fork
  3. after_fork
  4. after_worker_ready

ログとしては Kernel#exec した (１行目の executing) 後に before_exec がきているが、これはコードでなぜかそういう順番になっているだけで本当の順番は逆 ( https://github.com/defunkt/unicorn/blob/v5.3.0/lib/unicorn/http_server.rb#L455 )。 あとは起動時のときと同じログになる。

I, [2017-05-21T15:45:51.255441 #43971]  INFO -- : executing ["/Users/yuta-iwama/src/github.com/ganmacs/playground/ruby/unicorn-hook/vendor/bundle/ruby/2.4.0/bin/unicorn", "-c", "unicorn.ru", {9=>#<Unicorn::TCPSrv:fd 9>}] (in /Users/yuta-iwama/src/github.com/ganmacs/playground/ruby/unicorn-hook)
I, [2017-05-21T15:45:51.255758 #43971]  INFO -- : [before_exec]
I, [2017-05-21T15:45:51.497657 #43971]  INFO -- : inherited addr=0.0.0.0:8080 fd=9
I, [2017-05-21T15:45:51.497814 #43971]  INFO -- : [before_fork] worker=#<Unicorn::Worker:0x007ffc888f3018>
I, [2017-05-21T15:45:51.498835 #43971]  INFO -- : [before_fork] worker=#<Unicorn::Worker:0x007ffc888f2ca8>
I, [2017-05-21T15:45:51.499294 #43971]  INFO -- : master process ready
I, [2017-05-21T15:45:51.500538 #43982]  INFO -- : [after_fork] worker=#<Unicorn::Worker:0x007ffc888f3018>
I, [2017-05-21T15:45:51.500818 #43983]  INFO -- : [after_fork] worker=#<Unicorn::Worker:0x007ffc888f2ca8>
I, [2017-05-21T15:45:51.501025 #43982]  INFO -- : Refreshing Gem list
I, [2017-05-21T15:45:51.501152 #43983]  INFO -- : Refreshing Gem list
I, [2017-05-21T15:45:51.602740 #43983]  INFO -- : [after_worker_ready] worker=#<Unicorn::Worker:0x007ffc888f2ca8>
I, [2017-05-21T15:45:51.604692 #43982]  INFO -- : [after_worker_ready] worker=#<Unicorn::Worker:0x007ffc888f3018>

その他

自分は before_exec と before_fork の呼ばれるタイミングの違いがよくわかっていなかった。 before_exec は restart などをする時に unicorn コマンドを内部で叩く前、before_fork は ワーカープロセスを fork する直前呼ばれるみたい。