RubyのLoggerはスレッドセーフ(＆プロセスセーフ)かどうか調べてみた

Ruby の Logger ってスレッドセーフ(＆プロセスセーフ)なんだっけ？と疑問に思ったので調べてみました。特にマルチプロセス環境で Logger の shift_age オプションを使ってログローテーションさせようとした場合に大丈夫なのかな、と。

なお、検証コードには楽するために parallel gem を使用しましたが、特に問題なかろうかと思います。ほとんど同じインターフェースでマルチスレッドとマルチプロセスを切り替えられるので便利です。

マルチスレッドでログが混ざらないか
マルチプロセスでログが混ざらないか
マルチスレッドでのログローテーションは大丈夫か
マルチプロセスでのログローテーションは大丈夫か
まとめ

1. マルチスレッドでログが混ざらないか

コード

require 'logger'
require 'parallel'

logger = Logger.new("/tmp/test.log")
Parallel.map(['a', 'b'], :in_threads => 2) do |letter|
  300000.times do
    logger.info letter * 5000
  end
end

ログの出力

混ざりませんね

$ egrep -e 'ab' -e 'ba' /tmp/test.log
[空]
$ head -4 /tmp/test.log
I, [2013-09-29T22:35:32.816742 #29827]  INFO -- : aaaaaaaaaaaaaaaaaaa ...
I, [2013-09-29T22:35:32.823871 #29827]  INFO -- : bbbbbbbbbbbbbbbbbbb ...
I, [2013-09-29T22:35:32.816742 #29827]  INFO -- : aaaaaaaaaaaaaaaaaaa ...
I, [2013-09-29T22:35:32.823871 #29827]  INFO -- : bbbbbbbbbbbbbbbbbbb ...

考察

ソースコードを見ても mutex を使って排他制御しているので問題なさそうですね。

logger.rb#L559

    def write(message)
      begin
        @mutex.synchronize do
          ...
            @dev.write(message)
          ...
        end

2. マルチプロセスでログが混ざらないか

mutex で排他制御できるのはプロセス内のスレッド間までだよねー、ということでマルチプロセスな場合でも確認してみましょう。

コード

require 'logger'
require 'parallel'

logger = Logger.new("/tmp/test.log")
Parallel.map(['a', 'b'], :in_processes => 2) do |letter|
  300000.times do
    logger.info letter * 5000
  end
end

ログの出力

混ざりませんね

$ egrep -e 'ab' -e 'ba' /tmp/test.log
[空]
$ head -4 /tmp/test.log
I, [2013-09-29T22:35:32.816742 #29827]  INFO -- : aaaaaaaaaaaaaaaaaaa ...
I, [2013-09-29T22:35:32.823871 #29827]  INFO -- : bbbbbbbbbbbbbbbbbbb ...
I, [2013-09-29T22:35:32.816742 #29827]  INFO -- : aaaaaaaaaaaaaaaaaaa ...
I, [2013-09-29T22:35:32.823871 #29827]  INFO -- : bbbbbbbbbbbbbbbbbbb ...

考察

Linux のシステムコールである write(2) のドキュメントを読むと

Atomic/non-atomic: A write is atomic if the whole amount written in one
operation is not interleaved with data from any other process. This is
useful when there are multiple writers sending data to a single reader. 
Applications need to know how large a write request can be expected to
be performed atomically. This maximum is called {PIPE_BUF}. This volume
of IEEE Std 1003.1-2001 does not say whether write requests for more
than {PIPE_BUF} bytes are atomic, but requires that writes of {PIPE_BUF} or
fewer bytes shall be atomic.

との記載があり、PIPE_BUF(Linux では 4KB)のサイズより小さい場合は atomic なのでログが混ざることはないが、それより大きい場合は混ざることがある、というように読めます。

そこでログが混ざることを再現しようと頑張ってみたのですが、全く混ざりませんね！ logger.rb がなにかやっているのかと思い、open('filename', File::WRONLY | File::APPEND | File::CREAT) して IO#write してみたり、Parallel が何か悪いのかと Process.fork に変えてみたりもしましたが、やはり混ざりませんね！

そこで近所のRuby コミッター様に聞いてみたところ、

18:48 sonots: PIPE_BUF より大きい場合、混ざってもおかしくないんすよね？
18:48 shyouhei: パイプならありうる
18:48 sonots: パイプじゃないと、混ざらない？
18:51 shyouhei: writeが一発で書けないときは常識的に考えてブロックしますね。
19:11 kazuho: カーネル内部でロックとりますからねぇ
19:11 kazuho: カーネル内部というか linux の場合だと ext3 とか vfs の内部

とのことで、ローカルのディスクなら blocking で APPEND なファイルディスクリプタに大きいデータを write(2) する場合でも、排他制御しなくても混ざらないというファイナルアンサーを頂きました。

ということで問題なし！

追記：kazuho 先生がもう少し突っ込んで調べてくれました！「混ざる」条件はもう少し厳しい。kazuho++ => 同時にwrite(2)すると混ざるかどうか - kazuhoのメモ置き場

3. マルチスレッドでのログローテーションは大丈夫か

コード

require 'logger'
require 'parallel'

logger = Logger.new("/tmp/test.log", 3, 1024 * 10)
Parallel.map(['a', 'b'], :in_threads => 2) do |letter|
  300000.times do
    logger.info letter * 5000
  end
end

実行結果

エラーなし

ログファイル

$ ls -l /tmp/test*
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:03 /tmp/test.log
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:03 /tmp/test.log.0
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:03 /tmp/test.log.1

考察

これもまた mutex を使って排他制御しているので問題なさそうですね。

logger.rb#L559

    def write(message)
      begin
        @mutex.synchronize do
          ...
              check_shift_log
          ...
        end

4. マルチプロセスでのログローテーションは大丈夫か

コード

require 'logger'
require 'parallel'

logger = Logger.new("/tmp/test.log", 3, 1024 * 10)
Parallel.map(['a', 'b'], :in_processes => 2) do |letter|
  300000.times do
    logger.info letter * 5000
  end
end

実行結果

log writing failed. closed stream
log shifting failed. closed stream
log writing failed. closed stream
log shifting failed. closed stream
...

ログファイル

$ ls -l /tmp/test.log
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:10 /tmp/test.log
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:10 /tmp/test.log.0
-rw-r--r-- 1 sonots sonots 10806  9月 29 23:10 /tmp/test.log.1

考察

mutex での排他制御が利かないので、エラーメッセージが出てしまいましたね。

logger.rb#L629-L633

      (@shift_age-3).downto(0) do |i|
        if FileTest.exist?("#{@filename}.#{i}")
          File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
        end
      end

例えば、こんなシーケンスになるとエラーが出ますね．

Process A: FileTest.exist?("#{@filename}.#{i}") #=> true
Process B: FileTest.exist?("#{@filename}.#{i}") #=> true
Process A: File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}") #=> success
Process B: File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}") #=> error!

また、こんな処理順になると、

Process A: FileTest.exist?("test.log.1") #=> true
Process A: File.rename("test.log.1", "test.log.2")
Process A: FileTest.exist?("test.log.0") #=> true
Process A: File.rename("test.log.0", "test.log.1")
Process B: FileTest.exist?("test.log.1") #=> true
Process B: File.rename("test.log.1", "test.log.2") #=> test.log.2 が元々は test.log.0 だった内容で上書きされてしまう！
Process B: FileTest.exist?("test.log.0") #=> false

となり、test.log.1 が欠けた状態になりえますね。

5. まとめ

ということで、ログが混ざることは心配しなくてよさそうですが、マルチプロセスな環境においては Logger にログローテーションさせるのは避けた方がよさそうです。 logrotate などの外部のプロセスでローテートさせるようにしましょう。

尚、マルチプロセスでのログローテーションをサポートしていると謳っている logging という gem もありますが、rails4 対応もされてないですし、メンテナンスされてなさそうですね T T

以上、@sonots でした。

追記：2013/11/11 RubyのLoggerはプロセスセーフになりました。

sonots:blog