log4netで複数プロセスから同じファイルにログを出力する場合、どうなるのか気になる今日この頃。
「log4netはスレッドセーフ！」とか検索すると出てきますが実際に複数スレッドの状況下で実行するとどうなるんでしょうか。
LockingModelをどう設定するかによって挙動は変わるはずなので、その辺りの設定を変えつつ実験してみます。
目次
やろうとしていること
parallel.forを使用して、最大40プロセスから同時に同一のログファイルにログを出力しようとした場合の挙動の確認
ExclusiveLockの場合
別のプロセスが使用していてログを出力しようとしてもできなかった場合、以下の写真のようになります。
一瞬ウイルス拾ったかな？と思うような奇異な光景です。
ログを確認しようとしてフォルダを開いたらこのような状態になっていたらヒヤッとしますね…。
書き込みに失敗した場合、設定ファイルの「DatePattern」に設定されている値を増殖させるようです。
複数プロセスから出力する可能性がある場合、このモードを使ってはいけません。
現実には起こりえないとは思いますが、こうなってくるとファイル名の最大長になったときにどういう挙動となるのか気になります……。
というわけで、ファイルの最大長を超すように設定ファイルを触ってみました！
実際に実行してみたところ、windowsのファイル名の最大長(255文字)以上でlog4netから出力しようとして止まる、なんてことはありませんでした。247文字までは出力されたので、log4net側からパスの最大長を超えないように制御されているようです。
もちろん、今回の実行でlog4netから例外が発生することはありませんでした。(※log4netは基本的に例外時に呼び出されることを想定されている作りになっているので例外が発生しません)
実行結果はこんな感じです。
今回は1プロセス毎に通番を振ってその番号をログに出力するようにしています。
「1プロセスにつきログを20回出力した後、1秒待機しLog4netを開放する」
このような処理を書いて40プロセス同時に実行しました。(正確にはcpuを40コア積んでいるわけではないので完全に同時というわけではないですが……)
上のログの画像を見ると、プロセス26が20回連続でログを出力していて、その間に他のプロセスによるログが出力されていないことが分かります。
このことから、ExclusiveLockを使用してログを出力すると1プロセスが実行している間ずっとファイルを排他で掴んでいることが分かります。
もしかして、ExclusiveLockで大量に同じログファイルにファイルを出力するとボトルネックになる？
log4netからログに本当に書き込めない状況の場合、どういう挙動をするのか検証していきましょう。
40プロセスで20回ログを出力してから、4秒待機させてみる。
要するに、ログファイルを掴んでいる時間をさらに長くしたときに問題が起こるかという実験になります。
1回の実行で出力されたログの中身はこのような形でした。
20回ログを出力したはずなのに20件どころか半分の10件も出てません。
増殖したログファイルを全て確認しましたが、プロセス２のログはこのファイル上の10レコードのみでした。
出力できる状態になる前にプロセスがキルされたようです。
最初の2ファイルまでは20件出力されていたのですが、それ以上に増殖したログファイルの中身は徐々に減ってました。1件もログ出力ができていないプロセスもありました。
そういう状態であってもlog4netは何もエクセプションは出力しませんでした。標準出力も然り……です。
結果:ボトルネックにはならないが、無言でログ出力が止まる
やっぱり複数プロセスからログ出力する可能性があるのであれば、ExclusiveLockは使っていけませんね。気を付けましょう。
まあログが消えるような状況になる前にこんな不審な名前のログファイルが出力されている地点で調査することになるとは思いますが。
MinimalLockの場合
MinimalLockの場合もやはり、ファイルを掴む時間が短いだけで、同時に同一のファイルを出力しようとした場合、ExclusiveLockよりは少ないものの、ログファイルは増殖しました。
ExclusiveLockと違う点は1プロセスから連続ログが出力されないことですね。ログを1件出力するたびにファイルの占有を解除しているのでこのような事象が起こります。
それ以外の点はExclusiveLockと挙動はほぼ変りません。ちなみに、40プロセスから同時にログを出力した場合、ExclusiveLockと同じように無言でログ出力が止まってました。全体の半分くらいしか出力されてません。
InterProcessLockの場合
出力されたログは1ファイルのみでした。出力されたログの中身はどうでしょうか。
2000行ログが出力されています。今回は40プロセスで50回ずつログを出力処理を実行しました。理論上も2000行ログが出力されるのが正解です。ログが消えたりしてないことがわかります。
InterProcessLockはスレッドセーフと言えそうです。
まとめ
- InterProcessLockの場合のみスレッドセーフとなる。
- その他のモードの場合はログを同時出力になるような状況にならないと断言できる場合のみ使わないと事故る
うわどうしよう～～～。変な名前ログファイルがたくさんあるよ
こんな状況になったら、まずはLockingModelの設定値を確認してみましょう。
log4netの設定をどうするか迷っている場合は、以下の記事も役立ちます。
