🌏

Python(とGo)で複数プロセスから一つのファイルにログを書き込んでいいのか？

2022/10/10に公開

2件

概要

マルチプロセスでレスポンスの処理を行う（1リクエストにつき1プロセスがレスポンスの処理を行う）PythonのWEBフレームワーク^[1]でAPIサーバーを実装している際、各プロセスから一つのファイルにログを書き出しても、行が上書きされる・順番が前後するといった不整合がおきないのか、という疑問がわきました。（ファイルは各プロセスで独立にopenするものとします。）

Pythonのロギングに関する公式ドキュメントには、「複数プロセスから1ファイルへのロギングはサポートしていないから別の方法で工夫しろ」と書いてあるのですが、別の記事では「書き込むログの長さが短ければ不整合はおきない」と記述されていたり、よくわからなくなったので自分で調べてみました。

結論としては、Python標準のloggingモジュールでログの長さが2,147,479,552(=0x7ffff000)バイト以下なら「原子性」は保証されることを確認しました。またpythonのloggingモジュールを使用しなくても、以下のコードようにファイルを追記モードで開き直接ファイルに書き込みを行えば、同様にログの長さが2,147,479,552(=0x7ffff000)バイト以下なら「原子性」が保証されることを確認しました。

with open("/log/file/path", "a") as f:
	f.write("log message")

なお本記事では、ある対象がそれ以上細かい単位や要素に分割されない性質を「原子性」、ある対象の時間的な順序関係が正しく担保される性質のことを「一貫性」とし、これらが保証されないことを不整合と定義します。またある対象が「分割されることなくひとかたまりで」「原子性を保った状態で」という意味として「Atomicに」という表現を用います。

ファイルにログが書き込まれる流れ

本記事ではファイルにログが書き出されるまでの流れを「Pythonでの書き込み処理」と「Linuxでの書き込み処理」に分け、それぞについて、「原子性」と「一貫性」を確認していきます。

Pythonでの書き込み処理

Pythonのloggingモジュールでlogger.info("log message")のような形でログを書き込む場合、内部では一般的なファイル書き込みと同様に、openメソッドで開いたファイルにwriteメソッドを呼んでいるだけ^[2]なので、以下では一般的なファイル書き込みについて説明します。

実際のファイルの書き込みは OS によって行われるため、以下のようにファイルに対するPythonのwriteメソッドの呼び出しをすると、最終的にはOSにファイル書き込みを依頼するwriteシステムコールがPython によって呼ばれます。^[3]

with open("/log/file/path", "a") as f:
	f.write("log message")

しかし、ファイルに対する書き込みf.write("log message")が実行されて直ちにwriteシステムコールが呼ばれるわけではなく、多くのプログラミング言語と同様に、書き込む内容は一度バッファリングされます。オーバーヘッドの大きいファイルの書き込み処理を効率化するために、f.write("hoge")が呼ばれるたびにwriteシステムコールを呼ぶのではなく、Python側である程度書き込む内容を溜めてからまとめて一つのwriteシステムコールを呼んでいるわけです。この一時的な溜め込み場所をバッファといいます。

Pythonでの書き込み処理における「原子性」を確認するには、これらのバッファリングの機構に関わらず、Pythonのwriteメソッドに渡した文字列のかたまりがAtomicにwriteシステムコールに渡されることを確認すればよいです。

以下がPythonのwriteメソッドの実装です。

このメソッドの疑似コードが以下です。

擬似コード

if これから書き込む内容のサイズ <= バッファの残りサイズ:
	書き込み内容をバッファに入れる
	return
else:
	_bufferedwriter_flush_unlockedメソッドで既存のバッファ内容をファイルに書き込む
	while これから書き込む内容のサイズ > バッファサイズ:
		実際に書き込まれたサイズ <- _bufferedwriter_raw_writeメソッドで書き込み内容をファイルに書き込む
		これから書き込む内容のサイズ -= 実際に書き込まれたサイズ

	残った書き込み内容をバッファに入れる

1950行目で「これから書き込む内容のサイズ」と「バッファの残りサイズ」を比較しています。「これから書き込む内容のサイズ」<=「バッファの残りサイズ」の場合、書き込み内容をバッファに入れて終了します。「これから書き込む内容のサイズ」>「バッファの残りサイズ」の場合、まず1963行目で既存のバッファの中身の書き込みを行う_bufferedwriter_flush_unlockedメソッドを実行し、次に「これから書き込む内容のサイズ」が「バッファサイズ」よりも大きい場合、2020行目で実際にファイル書き込みを行う_bufferedwriter_raw_writeメソッドを実行します。_bufferedwriter_raw_writeは、以下のような引数を持ち

static Py_ssize_t  _bufferedwriter_raw_write(
	buffered *self,  // バッファの構造体へのポインタ
	char *start,     // 書き込み内容へのポインタ
	Py_ssize_t len   // 書き込みたいサイズ
)

実際にファイルに書き込まれたサイズを返すメソッドで、_bufferedwriter_flush_unlockedメソッドの中でも呼ばれており、内部で最終的にwriteシステムコールを実行します。したがってPythonでの書き込み処理における「原子性」を確認するには、書き込みたい内容のサイズがそのまま_bufferedwriter_raw_writeメソッドのlen引数に指定され、関数内で書き込み内容がAtomicにwriteシステムコールに渡されることを確認すればいいと言い換えられそうです。

実際、2020行目で最初に_bufferedwriter_raw_writeメソッドが実行される際は書き込み内容のサイズがそのままlen引数として指定される（buffer->lenが書き込み内容のサイズ、written変数ははじめ0で初期化される）ため、「原子性」の1つ目の条件はクリアしてそうです。

では実際に指定されたサイズの書き込み内容がそのままwriteシステムコールにAtomicに渡されるか確認していきます。このメソッドをもう少し追っていくと、最終的にwriteシステムコールを実行している以下のメソッドまでたどりつきます。

この関数のcount引数に_bufferedwriter_raw_writeメソッドで指定した書き込み内容のサイズが指定されます。擬似コードは以下です。

擬似コード

if 書き込みサイズ > 書き込み上限(_PY_WRITE_MAX):
	書き込みサイズ <- 書き込み上限(_PY_WRITE_MAX)

書き込みサイズでwriteシステムコールを実行
return 書き込みサイズ

環境依存のコードが多くなり読みにくいですが、1799行目で書き込みサイズが_PY_WRITE_MAXより大きければ、書き込みサイズを_PY_WRITE_MAXにするという処理があります。つまりPythonでの書き込み処理における「原子性」は、書き込みサイズが_PY_WRITE_MAXより大きければ保証されないことがわかります。GIL^[4]の有無で処理が分岐しますが、その後1810行目もしくは1825行目でwriteシステムコールを呼んでおり、第三引数に書き込みサイズcountを指定しています。以上より書き込みサイズが_PY_WRITE_MAXより小さければ、Python側での「原子性」は保証されることが確認できました。

なお、この_PY_WRITE_MAXの値は以下で定義されています。

PY_SSIZE_T_MAXは#define PY_SSIZE_T_MAX ((Py_ssize_t)(((size_t)-1)>>1))で定義されており結局_PY_WRITE_MAXはC言語のintやsize_t型の最大値に依存してるわけですが、これはPOSIXで範囲は定められているものの実際の値は実装依存となっています。手元のLinuxではsize_t型はlong unsigned int型で定義されていて^[5]、LONG_MAXは0x7fffffffだったので_PY_WRITE_MAXは $2^{64}$ だと思われます。したがって手元の環境では $2^{64}$ バイト、つまりだいたい $18\times10^6$ テラバイトくらいまではPython側での「原子性」は保証されるといえますが、現実問題このサイズの文字列を書き込むことはないと思うので特に意識する必要はなさそうです。システムによって $2^{32}$ バイト= $4$ GBくらいまでのことも多そうです。

処理の説明に戻ります。writeシステムコールは実際にファイルに書き込まれたサイズを返します。このサイズは_bufferedwriter_raw_writeメソッドの返り値として戻っていきます。_bufferedwriter_raw_writeメソッドのlen引数に指定した書き込みサイズより実際に書き込まれたサイズが小さい場合は、その残りがバッファサイズより小さければバッファに入れて終了します。そうでなければ再び_bufferedwriter_raw_writeメソッドを呼び、上記を繰り返します。以上でPythonの書き込み処理は終わりです。

ちなみに書き込む内容を保持する変数とバッファサイズにも最大サイズがあり、これらはそれぞれPy_ssize_t型の変数です。このサイズも実装依存となっています。

PythonのプロセスはOSにスケジューリングされているため、「一貫性」は保証されないです。

Linuxでの書き込み処理

アプリケーションからはwriteシステムコールを呼ぶことでファイル書き込みをOSに依頼することができます。writeシステムコールは以下のような定義で、返り値は実際にファイルに書き込まれたサイズです。

ssize_t write(
	int fd,          // ファイルディスクリプタ
	const void *buf, // 書き込み内容へのポインタ
	size_t count     // 書き込みサイズ
);

それでは、writeシステムコールにおける「原子性」が保証される条件を見ていきます。これはwriteのマニュアルページもしくはシェル上でman 2 writeを実行することで確認できます。

If the file was open(2)ed with O_APPEND, the file offset is first set to the end of the file before writing. The adjustment of the file offset and the write operation are performed as an atomic step.

これによればファイルを追記モードで開けば、書き込み直前にファイルの書き込み位置はファイルの最後に移動され、この書き込み位置の移動とファイル書き込みはAtomicに行われる、とのことです。このあたりの実際の処理は「(付録) 親プロセスがファイルをopenするケースでは」で詳細を確認しています。Pythonでは以下のようにopenメソッドの2つ目の引数に"a"を指定することで追記モードでファイルを開けます。

with open("/log/file/path", "a") as f:
	f.write("log message")

更にcount引数がSSIZE_MAXより大きかった場合の挙動として以下のような記述があります。

On Linux, write() (and similar system calls) will transfer at most 0x7ffff000 (2,147,479,552) bytes, returning the number of bytes actually transferred. (This is true on both 32-bit and 64-bit systems.)

Linuxでは実際に書き込めるのは0x7ffff000 (2,147,479,552)までとのことです。実際にこの判定を行っているのが以下のメソッドの586行目で、MAX_RW_COUNTが0x7ffff000を表しています。^[6]

上のwriteシステムコールを呼んでいたPythonのメソッドと同様に、書き込みサイズcountがMAX_RW_COUNTを超える場合はcountをMAX_RW_COUNTとしています。

以上よりLinux側での書き込み処理の「原子性」は、ファイルを追記モードで開き書き込み内容のサイズがMAX_RW_COUNT以下であれば保証されることがわかりました。

なお、writeシステムコールが実際に書き込む内容のサイズが引数に指定したサイズより小さくなることは、count引数がMAX_RW_COUNTより大きかった場合以外にも以下のようなケースが挙げられますが、本記事ではそういった例外はないことを前提とします。

Ctrl + Cのようなシグナルが途中で送られた
Diskの空きスペースがなくなった

おわりに

最後に「Pythonでの書き込み処理」と「Linuxでの書き込み処理」を合わせると、
「writeシステムコールの書き込み上限サイズMAX_RW_COUNT」<INT_MAX<=「Pythonのwriteメソッドの書き込み上限サイズ_PY_WRITE_MAX」であるため、結論としてはファイルを追記モードで開き、書き込みサイズがMAX_RW_COUNT=2,147,479,552(=0x7ffff000)バイト以下であれば、「原子性」が保証されるとなります。ちなみに、今回は各プロセスでファイルを別々にopenするという想定でしたが、親プロセスでファイルをopenし、そのプロセスをforkする形でマルチプロセスを行う場合は、追記モードでファイルを開く必要はありません。詳しくは「（付録）親プロセスがファイルをopenするケースでは」を参照ください。

(付録) `write`システムコールのあと

writeシステムコールを実行しても実際にはその値はバッファリングされて即座にDiskには書き込まれません。そのバッファのような部分のことをダーティページと呼びます。少し前にビット演算なんてどこで使われてるんだというツイートが流行ってダーティビットの話もありましたが、この変更されたファイルを記録するのがダーティビットです。ただし、バッファ内容を即座にDiskに反映するためのfsyncシステムコールやpythonのos.fsyncメソッド(システムコールのラッパー)も存在します。またファイルのopen時のモードでも指定できます。

(参考)

(付録) 親プロセスがファイルを`open`するケースでは

本記事は各プロセスで独立にファイルを開いて書き込みを行う想定でした。ここでは親プロセスでファイルを開き、そのプロセスをforkする形でマルチプロセスを実行しファイル書き込みを行うケースについて説明します。

まずはじめに、open file descriptionとファイルディスクリプタについて説明します。

open file description

writeシステムコールを呼んだ際に、その書き込み箇所（ファイルの先頭なのか・最後なのか・途中のどこかなのか）はopen file description^[7]を用いて管理しています。
このopen file descriptionは（プロセスごとではなく）システム全体で共有しているもので、各ファイルの現在位置のような情報（以降ファイルオフセット）を保持しており、writeシステムコールはそのファイルオフセットに書き込みを行い、書き込みを行った分だけファイルオフセットを後ろにずらす、ということを行います。open file descriptionはカーネルのコードにおいてはfile構造体に対応するものです。

またopen file descriptionはファイルをopenして作成する際に毎回作られます。つまり同じファイルに対して複数のopen file descriptionレコードが存在しうるということです。

ファイルディスクリプタ

ファイルディスクリプタはファイルなどを表す識別子で、openシステムコールの返り値やwriteシステムコールの1つめの引数で使用されるものです。カーネルは各ファイルディスクリプタがどのopen file descriptionを指しているかに関するテーブルをプロセスごとにもっています。ファイルをopenした際、open file descriptionが作成されるのと同時にそれを参照するファイルディスクリプタも作られるため、open file descriptionと同様、一つのファイルに対して複数のファイルディスクリプタを持つことがあります。Linuxで/proc/{PID}/fdディレクトリにいけば、各ファイルディスクリプタが何を指しているか確認できます。

https://myaut.github.io/dtrace-stap-book/kernel/fs.html より引用

上記画像のfdがファイルディスクリプタを表しており、fileという構造体がopen file descriptionを表しています。そして各file構造体が実際のファイルなどの実態を表すinodeへの参照を持っています。

親プロセスからforkした場合は、このopen file descriptionとファイルディスクリプタは親プロセスと共有されます。そしてwriteシステムコールにより、あるファイルディスクリプタを持つファイルに書き込みを行う際は、そのファイルディスクリプタに対応するopen file descriptionのファイルオフセットはロックされます。つまり、一つのプロセスでwriteシステムコールを実行すると、他のプロセスでも同じopen file descriptionを共有しているため、各プロセスでファイルオフセットも共有でき、「原子性」が保証されます。

逆に各プロセスでファイルを開いた場合は、同じファイルに対して複数のopen file descriptionが作成され、各プロセスで独立したファイルディスクリプタを持ちます。つまり、あるファイルで書き込みを行ってもある一つのopen file descriptionのファイルオフセットが更新されるだけで、同じファイルを表す別のopen file descriptionのファイルオフセットは更新されず、同じ行に書き込むというような不整合がおこる可能性があります。

ただし、本文でも述べたとおり、追記モードでファイルを開いて書き込みを行う場合は「原子性」が保証されます。これは追記モードでの書き込み時はopen file descriptionのファイルオフセットを使用しておらず、もっと低いレイヤでファイルの末尾のオフセットを取得しているためです。

具体的には、writeシステムコールのメソッドを追っていった先の以下のメソッドの3936行目でinodeのロックを取得し、

上記コードのgeneric_write_checksメソッドの中で呼ばれる以下のメソッドの1664行目で書き込む位置を現在のファイルサイズから取得し、更新しています。

open file descriptionは1ファイルに対して複数存在する可能性がありますが、inodeは1ファイルに対し1つのinodeが対応し、さらにそのinodeのロックを取得した状態でファイルのオフセットの更新と書き込みを行っているため、安全にマルチプロセスからAtomicな書き込みが実現されています。

(付録) Goでは

https://pkg.go.dev/log#Logger
上記ページに

A Logger can be used simultaneously from multiple goroutines; it guarantees to serialize access to the Writer.

との記載があります。ただし、これはあくまでもメインのgoroutineがLoggerの初期化を行い各goroutineでそのLoggerを共有する場合のことだと思われます。上述の通りファイルのopenでファイル作成を行うたびに、open file descriptionが生成されます。したがって各goroutineでLoggerの初期化を行えばやはりgoroutineごとに別のファイルディスクリプタとopen file descriptionをもつことになり、この記事の内容のようなことを気をつける必要があります。

以下がGoのWriteメソッドの実装です。

370行目でファイルディスクリプタのロックを取得していますが、上述の通り各goroutineで別のファイルディスクリプタを持つため、このロックはあまり意味をなしていないように思います。

一方、メインのgoroutineで初期化したLoggerを各goroutineで共有する場合は、ファイルディスクリプタとopen file descriptionも各goroutineで共有されているため、上記箇所でファイルディスクリプタのロックを取得することによりwriteシステムコールで一部しか書き込みが行われず複数回のシステムコールに分割された場合でもGo側でそれをAtomicな書き込みとして吸収することができ、writeシステムコールのサイズ等は特に気にする必要がなくなっています。

ただし、実際のところGoではLoggerなどはmainのgoroutineで初期化し、それを各goroutineで共有するのが普通かと思いますので、Goではシステムコールの長さは特に気にする必要はなさそうです。

脚注

WEBフレームワークにはDjangoを使用し、WSGIサーバーとしてgunicornを使用しました。workerの種類(リクエストを処理する各プロセスの種類)はSync Workersを使用しました。 ↩︎
コード上では、ファイルのオープンはここでされており、FileHandlerクラスの初期化時にmode引数などを指定できます。実際の書き込みはここで行われています。 ↩︎
Pythonで直接os.write("hoge")でシステムコールを呼ぶこともできます。 ↩︎
PythonはGlobal Interpreter Lock(GIL)というスレッドをロックする仕組みを持っています。したがってPythonのmultithreadライブラリなどでは並行処理は行なえますが並列処理は行なえず、PythonでCPUバウンドな処理を行うときはマルチスレッドではなくマルチプロセスを使う必要があります。しかし今回のようなファイル書き込みのIOバウンドな処理のときはスレッドのロックは不要　かつ無駄で、実際に1805行目でロックを開放していることがわかります。このようにGILはノンブロッキングIOのような性質も持ちます。 ↩︎
size_t型はPOSIXではunsigned int型と定めていますが、ANSI/ISO C（所謂C90など）では実装依存と定義されており、この場合はANSI/ISO Cが優先されるようです。 ↩︎
MAX_RW_COUNTはコード上では#define MAX_RW_COUNT (INT_MAX & PAGE_MASK)のように定義されています。上述の通りINT_MAXというのは実装依存の値なので、MAX_RW_COUNTは0x7ffff000に必ずなるわけではないように思うのですが、ここは分りませんでした... Linuxビルド時には固定されたINT_MAXを使っているのでしょうか。ご存じの方がいらっしゃったらコメントください。 ↩︎
この単語はシステム全体で開かれているファイルを管理しているテーブルのレコード表すためにPOSIXで使われているものです。open file descriptionはopen file object、file handle、open file table entryとも呼ばれます。 ↩︎

Discussion

kzm4269 2022/10/13

複数プロセスからの追記書き込みの仕様を理解していなかったので勉強になりました！
とはいえ先のコメントで書かれているように細かい事考えずに複数ファイルにログを残しておいて、
読むときに結合して時刻でソートするほうが楽ですよねー。

Takehisa Oyama 2022/10/15

そうですね。
最近のシステムは標準出力に出して、それをfluentdなどで集計することが多い気がするのであまりファイルは使われないのかもしません。