Pythonでmultiprocessing使用時にloggingの出力がダブる

Question

起きている問題

Python 3.5 で multiprocessing を使い並列処理を行うスクリプトを書いています。処理自体はうまくいっているのですが、logging でログを記録した際、同じメッセージが複数回出力されてしまいます。

ダブって出力されてしまうメカニズム・回避方法を教えてください。

該当のソースコード

import multiprocessing
import logging
import time
import os

class Hoge:
    def __init__(self):
        self.logger = logging.getLogger('HogeClass')
        self.logger.addHandler(logging.StreamHandler())
        self.logger.setLevel(logging.DEBUG)

    def child(self, num):
        self.logger.info('I am {}, pid {}'.format(num, os.getpid()))
        time.sleep(1)


if __name__ == '__main__': 
    def mp_hoge(num):
        h = Hoge()
        h.child(num)
    
    multiprocessing.Pool(2).map(mp_hoge, range(10))

実行時ログ

$ ./mp_test.py
I am 0, pid 13604
I am 2, pid 13605
I am 3, pid 13605
I am 3, pid 13605
I am 1, pid 13604
I am 1, pid 13604
I am 4, pid 13605
I am 6, pid 13604
I am 6, pid 13604
I am 6, pid 13604
I am 4, pid 13605
I am 4, pid 13605
I am 7, pid 13604
I am 7, pid 13604
I am 7, pid 13604
I am 7, pid 13604
I am 5, pid 13605
I am 5, pid 13605
I am 5, pid 13605
I am 5, pid 13605
I am 8, pid 13605
I am 8, pid 13605
I am 8, pid 13605
I am 8, pid 13605
I am 8, pid 13605
I am 9, pid 13605
I am 9, pid 13605
I am 9, pid 13605
I am 9, pid 13605
I am 9, pid 13605
I am 9, pid 13605

Answer 1

マルチプロセス環境で複数のプロセスから単一ファイル(標準エラー出力等も単一ファイルの一種です)へのログ記録自体がサポートされていません。

Logging クックブック — Python 3.5.2 ドキュメント#複数のプロセスからの単一ファイルへのログ記録

ログ記録はスレッドセーフであり、単一プロセスの複数のスレッドからの単一ファイルへのログ記録はサポート されています が、 複数プロセス からの単一ファイルへのログ記録はサポート されません 。

つまり、そもそもがサポートされない方法を使っていると言うことです。上記クックブックに複数プロセスからも単一のファイルに書き込む方法が記載されていますので、ご参考ください。

---

【蛇足】

では、なんでそうなるのか…ですが、ソースコードレベルまで確認して訳ではありませんので、以下はただの推測です。たぶん、間違っているような気がしますので、詳しい人はツッコミをお願いします。

multiprocessingは(UNIX/Linuxの場合)通常forkで子プロセスを作ります。logginはgetLogger()で同じインスタンスを返すために、親側に大本が既にあると考えられます。通常、fork内のオブジェクト(メモリ上のデータ)は親からのコピー(実際はコピーに見せかけですが)ですので、親と子のそれぞれは独立します。しかし、loggingは同じインスタンスを返すために、共有メモリ(みんなが一緒に見ているところ)に、全ての共通として存在する必要があると考えられます。つまり、forkした子供達にも同じloggingが存在し、getLogger()は同じ物を返しているのではないかと考えられます。

さて、getLogger()でインスタンス取得して出力するとき、何が起こるのでしょうか？そのロガーインスタンスはその子プロセスの標準エラー出力と結びつけられると考えられます。ですが、子プロセス間でインスタンスは共通です。でも、それぞれのプロセスで出力先はそれぞれ設定されています。

つまり、ログをとりあえず入れておくバッファは、共有メモリ上の同じインスタンスなので、子プロレス間で共通になっていると思われます。それをいざ出力するとなったとき、それぞれの子プロセスで標準エラー出力に結びつけられているため、その数だけ標準エラー出力に出力されるのでは無いかと考えられます。子プロセスが終了すれば、結びつけは終わりますので、今動いているプロセス数だけが出力され、数も一定にはなりません。

こうして考えるとなんとかうまく説明できそうですが、4と6の挟んであるところは何？と言われると…うーん、ちょっとわからないです。

Comments

[miyahan]

回答ありがとうございます。ちゃんと公式リファレンスを読むべきでした…。そこに次のような記述がありました。

> 同じ name で getLogger() を複数回呼び出すと、常に同じロガー・オブジェクトへの参照が返されます。

つまり本事象は、新しくロガーのインスタンスを生成してそこにハンドラを１つセットしていたつもりが、実は１つのロガーにハンドラをいくつもセットしていたため、同じログが複数回出力されていたようです。

そこで、ロガーオブジェクトをクラス変数に格納し、Hogeクラスの各インスタンスで使いまわすことにより問題は解決しました。

また指摘いただいた「複数のプロセスからの単一ファイルへのログ記録」の問題については、別途クックブックを参考に改良したいと思います。

ありがとうございました。