概要

現状、1処理が0.0012秒程度で終わるシステムがある。1回の処理は非常に短いが、これが呼ばれる回数は1処理あたり数百万回にも及ぶ。 速度がそれなりに求められる案件だ。

しかし、その中で何度かログファイルに書き出したいタイミングというのがある。それぞれのログファイルに書き出すタイミングは呼び出しの中では1度だけだ。 だが、「処理時間が短くて」「回数が多い」のに共有のログファイルに書くというのはなかなか鬼門だ。 ファイルに書いている時間に待ち合わせがあると、速度に対してものすごくロスが発生する。

まずは普通に

普通に共有されているログファイルをロックする方針でやってみる。

#!/usr/bin/ruby

20.times do |n|
  fork do
    100000.times do |i|
      File.open("#{ENV["HOME"]}/logtest/log", "a") do |f|
        f.flock(File::LOCK_EX)
        f.puts "LOGGED \##{i} with #{n}"
        f.flock(File::LOCK_UN)
      end
    end
  end
end

Process.waitall

ログファイルにアクセスできるのは1プロセスだけなので、同時にログに書こうとすると待たされることになる。 同時に書くとファイルが壊れてしまうので、すごく妥当な方法なのだが…

% time ruby test-logging1.rb
ruby test-logging1.rb  20.24s user 676.50s system 1102% cpu 1:03.18 total

1分3秒ということでかなり長い。

ソケットで投げてみる

UNIXドメインソケットにして投げつけてみる。 サーバー側が受け取った後の処理はクライアント側の処理時間には影響しないので、サーバーは投げ捨てる。

#!/usr/bin/ruby

require 'socket'

UNIXServer.open("#{ENV["HOME"]}/logtest.sock") do |sock|
  while s = sock.accept
    Thread.new(s) do |ts|
      ts.read
    end
  end
end

クライアントは直接ファイルに書くのではなくUNIXドメインソケットを使う。

#!/usr/bin/ruby

require 'socket'

20.times do |n|
  fork do
    100000.times do |i|
      UNIXSocket.open("#{ENV["HOME"]}/logtest.sock") do |sock|
        sock.puts "LOGGED \##{i} with #{n}"
      end
    end
  end
end

Process.waitall

待ち合わせは全く発生しないわけではない(ソケットを受付てからスレッドに移るまでの間はブロックされる)が、速くなるはずだと思うのだが。

% time ruby test-logging2.rb
ruby test-logging2.rb  25.51s user 33.05s system 62% cpu 1:33.02 total

1分33秒。却って遅くなってしまった。 やはりソケットに接続するコストが高いようだ。

ただ、並列数としては今回の場合最大24で、繰り返しの間というのは別にソケットをつなぎ直す必要はない設計になっている。 そのため、ループの外側に接続を置くことができる。

#!/usr/bin/ruby

require 'socket'

20.times do |n|
  fork do
    UNIXSocket.open("#{ENV["HOME"]}/logtest.sock") do |sock|
      100000.times do |i|
        sock.puts "LOGGED \##{i} with #{n}"
      end
    end
  end
end

Process.waitall

1行入れ替えただけだが、効果てきめん。

% time ruby test-logging2.rb
ruby test-logging2.rb  2.91s user 2.63s system 1488% cpu 0.373 total

今度は0.3秒で終わった。 Linuxの場合ソケットへの書き込みはカーネルがバッファするため、この程度の量であればメモリへの書き込みだけで終了する。そのため、かなり高速である。

ちなみに、ファイルの場合共有されているファイルをみんなが開いていたらぐちゃぐちゃになってしまうのでこの方法は使えない。 また、親子関係にある別プロセスについてはファイルディスクリプタ自体は共有されているため、fd番号さえわかっていれば共有できるのだが、 その場合は同じ経路から出ていくことになり、ファイルを共有した場合と同じ問題に直面するため、バグになってしまう。

PIDを使う

私の新しいアイディアは、「ログファイルにPIDを含める」という方法だ。

プロセス自体がマルチスレッドになっていなければ、その瞬間には同一PIDのプロセスはそのプロセスしかいないため、そもそもロックする必要がない。 ファイルのロックはあくまで「同時に」書かれるから必要になるのであって、どれだけ速くても順次であれば何も問題はないのだ。

#!/usr/bin/ruby

20.times do |n|
  fork do
    100000.times do |i|
      File.open("#{ENV["HOME"]}/logtest/log.#{$$}", "a") do |f|
        f.puts "LOGGED \##{i} with #{n}"
      end
    end
  end
end

Process.waitall

ファイル名にPIDを含めているため、同時に走っている別のプロセスが同じファイルにアクセスすることはない。 もちろん、これは並列化の方法にプロセスを選択している場合だけだが。

% time ruby test-logging3.rb
ruby test-logging3.rb  12.26s user 22.37s system 1778% cpu 1.948 total

なかなか速い。だが、ソケットとはだいぶ差があるようだ。 しかし考えてみればこれもプロセスをオープンしてからであればなにもループのたびに開き直す必要はない。ソケットと同じ話だ。 そこで、ソケットと同じく順序を入れ替えてみる。

#!/usr/bin/ruby

20.times do |n|
  fork do
    File.open("#{ENV["HOME"]}/logtest/log.#{$$}", "a") do |f|
      100000.times do |i|
        f.puts "LOGGED \##{i} with #{n}"
      end
    end
  end
end

Process.waitall

ループのたびにファイルを開くのではなく、予めファイルを開いてループで書いていくようにした。

% time ruby test-logging3.rb
ruby test-logging3.rb  2.52s user 0.13s system 1356% cpu 0.196 total

ファイルとソケットのオープンコストの差か、ソケットよりも速くなった。 ちなみに、ソケットを一回だけ開く方法よりも速い。

「forkでの並列処理に追記のログファイルはファイル名にPIDで」、このテクニック、私はどこかで見た記憶はないのだが、かなり有用だと思う。お勧めだ。