キャッシュしたデータが消える!?prefork型HTTPサーバーUnicornでドはまりしたメモ

HTTPサーバーUnicornを使っていてドはまりしたのでメモ。
主に、Unicornで動かすRackアプリでの変数スコープとpreload_appについて。

サマリ

Uncornは、RackアプリケーションのためのHTTPサーバーです。
HTTPリクエストを、メインプロセスからforkした子プロセスで処理するアーキテクチャが特徴。
- スレッドとかは使いません。
forkした子プロセスは、それぞれ別のメモリ空間を持つので、
- HTTPリクエストの処理間で、状態(変数の値)が共有されません。
  - ある処理で変数の値を変更しても、別の子プロセスで処理しているHTTPリクエストでは変数値は変わりません。
  - ただし、子プロセスが同じ場合は、状態が引き継がれます。(処理が終わった子プロセスは、次のHTTPリクエストで使いまわされます)
- 状態が共有されないので、スレッドセーフティを考慮した実装にする必要もありません。
- もし、メモリリークしても、子プロセスを再作成すればOK。

ドはまりした状況を再現する

↓のような、オンメモリキャッシュを作っていました。

Singleton インスタンスにキャッシュデータを格納して共有。
Singleton なので、同じRuby VM上なら共有されるはず。

# coding: utf-8

require 'sinatra/base'
require 'singleton'

# キャッシュ
class Cache
  include Singleton
  
  def initialize
    @store = {}
    @mutex = Mutex.new
  end
  
  def create_or_get(key, &generator)
    @mutex.synchronize {
      unless @store.include? key
        puts "cache is not exists. key=#{key}"
        @store[key] = generator.call
      else
        puts "cache exists. key=#{key} value=#{@store[key]}"
      end
      @store[key]
    }
  end
  
end

class App < Sinatra::Base
  get '/' do
    Cache.instance.create_or_get(:date) { DateTime.now.iso8601 } 
  end
end

リクエストを何回か投げてみます。

cache is not exists. key=date
10.0.2.2 - - [14/Feb/2015 12:32:18] "GET / HTTP/1.1" 200 25 0.0587
cache exists. key=date value=2015-02-14T12:32:18+09:00
10.0.2.2 - - [14/Feb/2015 12:32:19] "GET / HTTP/1.1" 200 25 0.0021
cache exists. key=date value=2015-02-14T12:32:18+09:00
10.0.2.2 - - [14/Feb/2015 12:32:21] "GET / HTTP/1.1" 200 25 0.0084
cache is not exists. key=date ★
10.0.2.2 - - [14/Feb/2015 12:32:22] "GET / HTTP/1.1" 200 25 0.0234
cache exists. key=date value=2015-02-14T12:32:22+09:00
10.0.2.2 - - [14/Feb/2015 12:32:26] "GET / HTTP/1.1" 200 25 0.0071

キャッシュされたはずのデータが、、消えてる・・・!?・・・って、Unicornの仕組みを考慮すれば、そりゃそうなんですが。
恥ずかしながら、その辺の仕組みを知らずに何気なく使っていた私は、ドはまりしました。

最初は、キャッシュへの投入がどこかで失敗してる?と思ってデバッグするも、そんなことはなく。
次に、Cacheのインスタンスが違うものになっている可能性を考え、object_idを確認。しかし、格納時/参照時とも、同じインスタンスが使われていました。
- 後述するprefork_app=trueにしてたので、forkした子プロセスはメインプロセスからコピーしたアドレス空間を共有します。
- なので、object_idもまったく一緒になるのです。

そもそもforkとは何か

fork（フォーク）とは、プロセスのコピーを生成するものである。
...
forkが呼び出されると、子プロセスのためのアドレス空間が新たに作成される。子プロセスのアドレス空間には親プロセスが持っていた全セグメントのコピーがあるが、コピーオンライト機能によって実際の物理メモリの確保は遅延される

Wikipedia:fork より

forkとは、プロセスのコピーを生成するもの
forkしてできた子プロセスは、独自のアドレス空間を持つ。
また、子のアドレス空間には、親プロセスが持っていた全セグメントのコピーが作成される。
この時、メモリを全コピーするとコストが高いので、コピーオンライトの仕組み提供されている。
- fork時に、実際にはメモリの値をコピーせず、親子で共有する。
- 子プロセスがメモリを書き換えたときに、そのページだけコピーを作成して使用する。

ふーむ。

preload_app

さて、この仕組みだとすべてのプロセスがRuby VMをごっそり持つので、

- メモリたくさん食うんじゃね?
- 子プロセスごとにRackアプリのロードが走って遅いんじゃね?

とか思うわけですが、このあたりの問題を回避する仕組みとして、preload_app(の設定)があります。

preload_app=trueにすると、メインプロセス内でアプリのロードが行われ、fork時にまるまる複製されるようになります。なので、子プロセス側でのロードは発生しません。また、コピーオンライトの仕組みでメモリも大部分が共有されるので、実メモリの使用量も少なくて済みます。

ということで、検証。
ロードに時間がかかる状態をエミュレーションするアプリを作ります。

# coding: utf-8

require 'sinatra/base'
require 'singleton'


puts "start loading."
sleep 5
puts "end loading."

class LazyApp < Sinatra::Base
  get '/' do
    "Lazy"
  end
end

preload_app=true で起動すると、子プロセスのforkの前に1度だけロードが走ります。

I, [2015-02-14T14:42:14.329315 #8117]  INFO -- : Refreshing Gem list
start loading.
end loading.
I, [2015-02-14T14:42:19.411606 #8117]  INFO -- : listening on addr=0.0.0.0:5000 fd=9
I, [2015-02-14T14:42:19.411817 #8117]  INFO -- : worker=0 spawning...
I, [2015-02-14T14:42:19.413196 #8117]  INFO -- : worker=1 spawning...
I, [2015-02-14T14:42:19.413949 #8144]  INFO -- : worker=0 spawned pid=8144
I, [2015-02-14T14:42:19.415228 #8117]  INFO -- : worker=2 spawning...
I, [2015-02-14T14:42:19.416395 #8117]  INFO -- : master process ready
I, [2015-02-14T14:42:19.416847 #8144]  INFO -- : worker=0 ready
I, [2015-02-14T14:42:19.417557 #8149]  INFO -- : worker=2 spawned pid=8149
I, [2015-02-14T14:42:19.418379 #8147]  INFO -- : worker=1 spawned pid=8147
I, [2015-02-14T14:42:19.421307 #8149]  INFO -- : worker=2 ready
I, [2015-02-14T14:42:19.421429 #8147]  INFO -- : worker=1 ready

preload_app=false だと、forkされたプロセスの数だけ、最初にロードが走ります。

I, [2015-02-14T14:45:24.395364 #8154]  INFO -- : listening on addr=0.0.0.0:5000 fd=9
I, [2015-02-14T14:45:24.395553 #8154]  INFO -- : worker=0 spawning...
I, [2015-02-14T14:45:24.397392 #8154]  INFO -- : worker=1 spawning...
I, [2015-02-14T14:45:24.398156 #8181]  INFO -- : worker=0 spawned pid=8181
I, [2015-02-14T14:45:24.398442 #8181]  INFO -- : Refreshing Gem list
I, [2015-02-14T14:45:24.398412 #8154]  INFO -- : worker=2 spawning...
I, [2015-02-14T14:45:24.399575 #8184]  INFO -- : worker=1 spawned pid=8184
I, [2015-02-14T14:45:24.399857 #8184]  INFO -- : Refreshing Gem list
I, [2015-02-14T14:45:24.401218 #8154]  INFO -- : master process ready
I, [2015-02-14T14:45:24.401716 #8187]  INFO -- : worker=2 spawned pid=8187
I, [2015-02-14T14:45:24.402049 #8187]  INFO -- : Refreshing Gem list
start loading.
start loading.
start loading.
end loading.
end loading.
end loading.
I, [2015-02-14T14:45:29.529195 #8184]  INFO -- : worker=1 ready
I, [2015-02-14T14:45:29.533661 #8187]  INFO -- : worker=2 ready
I, [2015-02-14T14:45:29.541946 #8181]  INFO -- : worker=0 ready

JavaでTomcatな世界しか知らないと、こんなところではまったりします。うーむ。