flock リベンジ
唐突だが、前々から不審を抱いていた LaCoocan サーバの flock の挙動を検証してみた。
サーバ側 : flock を取得して 5 秒 Sleep する
#!/usr/local/bin/ruby -Ku require 'logger' LOGFILE='logfile.log' LOCKFILE = '.lockfile' def main open(LOGFILE, 'a') do |logfile| logfile.sync = true logger = Logger.new(logfile) logger.info("try") logfile.fsync open(LOCKFILE, "w").flock(File::LOCK_EX) logger.info("get lock") logfile.fsync sleep 5 logger.info("release lock") logfile.flush logfile.fsync end end main puts "Content-type: text/plain\n\n" print "ok."
※ LaCoocan サーバで Ruby の Logger を使うにはひと手間要る。
※ logfile.fsync を外すと Logger の排他が甘いのかマルチプロセス下ではログファイルが壊れる。
クライアント側 : サーバ側スクリプトに 10 プロセスで同時にアクセスする
#!/usr/local/bin/ruby -Ku require 'net/http' 1.upto(10) do |num| fork do start = Time.now print sprintf("%02d: ", num) print Net::HTTP.get('asagi.la.coocan.jp', "サーバ側スクリプトパス") puts sprintf("[%f]", Time.now - start) end end Process.waitall puts 'done.'
※ どうでもいいがシングルクォートとダブルクォートの統一性がないのが見苦しいな。
結果
08: ok.[5.148718] 01: ok.[5.237007] 03: ok.[10.162105] 09: ok.[10.213529] 10: ok.[15.215000] 04: ok.[20.225915] 06: ok.[25.211780] 05: ok.[30.385823] 02: ok.[35.405181] 07: ok.[40.396211] done.
ご覧の通り、08 と 01、03 と 09 で排他制御に失敗している。
Logger 出力
I, [2007-03-17T21:51:15.444839 #27675] INFO -- : try I, [2007-03-17T21:51:15.445020 #27676] INFO -- : try I, [2007-03-17T21:51:15.448955 #27675] INFO -- : get lock I, [2007-03-17T21:51:15.496874 #18512] INFO -- : try I, [2007-03-17T21:51:15.498736 #18517] INFO -- : try I, [2007-03-17T21:51:15.498963 #18518] INFO -- : try I, [2007-03-17T21:51:15.501031 #18516] INFO -- : try I, [2007-03-17T21:51:15.501341 #18519] INFO -- : try I, [2007-03-17T21:51:15.501617 #18515] INFO -- : try I, [2007-03-17T21:51:15.502126 #18513] INFO -- : try I, [2007-03-17T21:51:15.502451 #18514] INFO -- : try I, [2007-03-17T21:51:15.505188 #18512] INFO -- : get lock I, [2007-03-17T21:51:20.444564 #27675] INFO -- : release lock I, [2007-03-17T21:51:20.447676 #27676] INFO -- : get lock I, [2007-03-17T21:51:20.516224 #18512] INFO -- : release lock I, [2007-03-17T21:51:20.519186 #18516] INFO -- : get lock I, [2007-03-17T21:51:25.447672 #27676] INFO -- : release lock I, [2007-03-17T21:51:25.516093 #18516] INFO -- : release lock I, [2007-03-17T21:51:25.518713 #18519] INFO -- : get lock I, [2007-03-17T21:51:30.515994 #18519] INFO -- : release lock I, [2007-03-17T21:51:30.520071 #18515] INFO -- : get lock I, [2007-03-17T21:51:35.515843 #18515] INFO -- : release lock I, [2007-03-17T21:51:35.518961 #18518] INFO -- : get lock I, [2007-03-17T21:51:40.519052 #18518] INFO -- : release lock I, [2007-03-17T21:51:40.522297 #18517] INFO -- : get lock I, [2007-03-17T21:51:45.525582 #18517] INFO -- : release lock I, [2007-03-17T21:51:45.678031 #18513] INFO -- : get lock I, [2007-03-17T21:51:50.685459 #18513] INFO -- : release lock I, [2007-03-17T21:51:50.688216 #18514] INFO -- : get lock I, [2007-03-17T21:51:55.685333 #18514] INFO -- : release lock
上は時系列順にソートしてある。#27675 が 08、#18512 が 01、#27676 が 03、#18516 が 09 だな。
