Pythonのloggingモジュールを使って、multiprocessingモジュールで作成された複数のプロセスから同じファイルにログを書き込んだらどうなるか検証してみました。
なぜ検証しようと思ったか
Pythonのloggingモジュールは、マルチプロセス(multiprocessing)から同じファイルへのログの出力をサポートしていないことがドキュメント(Logging to a single file from multiple processes)に明記されています。
もしマルチプロセスから同じファイルにログ出力をしたいのであれば、ソケット通信、ロック、キューなどのテクニックを使うといいよと案内されていることもあり、ネット上の情報としても多くの方がそれに従っている感じですね。
でもそれってぶっちゃけ、面倒じゃね！？
ということで、もし対策を怠った状態で同じファイルに出力してしまったらどんな悲劇が起こるのか？ということを確認してみることにしました。
検証前に関連する情報を調査
検証の前に、なぜマルチプロセスからのログ出力が対応していないのか？といった部分にまつわる情報を調べました。
- Pythonは複数プロセスから同じファイルへ順序付けてアクセスする標準的な手段を提供していない。（Logging to a single file from multiple processesより）
- ファイルへのアクセスは実行環境で定められたパイプバッファサイズ単位で行われる。
- パイプバッファサイズ以下の書き込み中に他の書き込みが割り込むことは無い。（この性質をAtomicityという。）
- Linux2.6.11（2016年）時点のパイプバッファのサイズは4KBなので、4KB以下のログ書き込みは割り込まれない。
- 2021年現在のMacOSやLinuxのパイプバッファのサイズは64KB以上なので、ほぼ全てのログ書き込みは割り込まれないはず。
ソケット・ロック・キューなんて使う必要、ないんじゃないかって気がしてきました。これを証明するために検証してみましょう。
複数プロセスから1つのファイルにログを書き出す検証
プロセスを3つ起動して、それぞれのプロセスから同じログファイルにログを100行ずつ書き出すプログラムを作成して検証しました。
検証結果を正しく出すため、次のことを意識しました。
- 書き出すログの長さは12KBほど。これはutf-8で日本語文字およそ1100文字ぶん。（こんな長いログは例外出力くらい？）
- ログ書き出しごとにランダムな時間設定でスリープ。偶然の同時書き込みが誘発されることを狙う。
といったコンセプトで作成した検証プログラムを紹介おきますが、ちょっとプログラムが長くなっちゃいました。。本題の内容には直接影響しない部分なので読み飛ばしちゃってダイジョーブです。
from logging import getLogger
from ruamel.yaml import YAML
from pathlib import Path
from logging.config import dictConfig
from time import sleep
from multiprocessing import Process
import random
def logging_demo(c):
""" 開始されたプロセス。ログに1000回書き出す。
1度の書き出しサイズは一般的なパイプバッファである
4KB(4096バイト)の3倍ちょい。
"""
# ログをファイル"logfile"に書き出す設定をロード
config_path = Path('config.yml')
config_content = YAML().load(config_path)
dictConfig(config_content)
logger = getLogger()
for i in range(100):
# 'あ'などの文字を一般的なパイプバッファである
# 4KBの3倍長出力する。
# （'あ'はutf-8では3バイト長なので4096*3倍バイトになる）
# バッファを超えた部分の出力順が入れ替わるか？を確認。
logger.debug(f'{i:02n} {c*4096}')
# 0.01〜0.1秒だけ停止
sleep(random.random() * 1e-1)
def main():
""" ログを書き出しまくるプロセスを3つ開始 """
for c in ['あ', 'い', 'う']:
p = Process(target=logging_demo, args=(c,))
p.start()
p.join()
if __name__ == '__main__':
main()
それとプログラムから参照しているconfig.yml
version: 1
formatters:
common:
format: '{asctime} {message}'
style: '{'
handlers:
root:
class: logging.FileHandler
filename: logfile
encoding: utf-8
formatter: common
root:
level: DEBUG
handlers: [root]
Mac OS MontereyとLinux5.10.47の2つの環境で実行して確認しました。（どちらも最新の環境なのでおそらくパイプバッファは64KB以上）
プログラムを実行すると、logfileというファイルが作成されます。nanoで開くとこんな感じで見れます。
この結果に対して次の2点を確認しました。
- ログが時間順に並んでいるか
- 出力した300行全てが正しい書式か
まずログが時間順に並んでいるかはsortコマンドで確認できます。
$ sort -s -c -k 1,2 logfile
sortコマンドはファイルの内容をソートするコマンドですが、-cオプションを付けるとソートされているかどうかをチェックする挙動になります。
-kオプションで、スペース区切りで何番目のフィールドの情報を使うかを指定します。-k 1,2としているので、最初の"2021-11-03"というフィールドと２番目の"15:57:48,682"というフィールドの情報を使うことになります。
-sオプションは、-kオプションで指定した以外のフィールドを無視したいので指定しています。
確認の結果、logfileのログは、全て時間順に並んでいました。
次に、出力した300行全てが正しい書式かの確認です。これは正規表現で確認しました。
$ cat logfile | grep -E '2021-11-03 15:57:[0-9]{2},[0-9]{3} [0-9]{2} [あいう]*' | wc -l
まずcatコマンドでファイル全体を読み出し、grepコマンドに渡します。
grepコマンドに-Eオプションを付けるとperlなどで使われる形式の正規表現でのマッチングができます。
そしてgrepでマッチされた出力をwcコマンドに渡して行数をカウントしました。
結果、300となり、出力崩れは発生していないことが確認できました。
つまり、複数のプロセスから1つのファイルに対してログ出力をしまくっても、特に問題にはならなかった。という結果になりました。
ちなみに今回検証できたのは、1つのPythonプログラムから複数のプログセスを起動した場合だけなので、違う条件だとこうはいかない…という可能性は否定できないです。
結論
- Pythonのloggingモジュールを使ってマルチプロセスから同じファイルにログを書き込んでも、問題にならない。
- コスパを考えたらテスト環境とかなら対策しなくてもよさげ。
- パイプバッファの拡張により数年前とは事情が変わったということだろうか。
