Pythonシミュレーションにおけるlogging活用のススメ
最近、業務でPythonシミュレーションを行っており、Python標準ライブラリのloggingが便利だったのでメモしておく。
結果を出力する最も単純なコマンドはprintだが、これは機能に乏しく、tqdmのバーと一緒に表示したい、ファイルにも書き込みたいなどの要求が出てきたときには力不足である。
このような用途で役に立つのが、Python標準ライブラリのloggingである。
loggingの使い方に関する記事は乱立しており、初心者には正直理解しづらい。個人的には、以下の記事を参考にするのがよいと思う。
qiita.com
単純なユースケースなら上記記事で問題ないと思われるが、シミュレーションログ用途に特化したい場合には多少の変更が必要になり、これを以下に示す。 やりたいことは以下の二つである。
- tqdmのバー表示を邪魔しない形で標準出力にログを出す
- シミュレーション終了時にまとめてファイルにログを書き出す
1.に関しては、シミュレーションでループを回す際に用いるtqdmの邪魔をしない形でログを吐きたいという意図であり、以下の記事がまさにその答えである。
logging.Handlerクラスを継承したTqdmLoggingHandlerを実装すればよい。
stackoverflow.com
例えば以下のように使う。
import logging logger = logging.getLogger() logger.setLevel(logging.DEBUG) formatter_tqdm = logging.Formatter("{message}", style="{") tqdm_handler = TqdmLoggingHandler(level=logging.INFO) tqdm_handler.setFormatter(formatter_tqdm) logger.addHandler(tqdm_handler)
2に関しては、できるだけファイルIOを減らして高速化したいという意図。MemoryHandlerを使ってログをバッファに溜め、最後にファイルに書き込むようにすれば実現できる。これは例えば以下のように書く。
import logging logger = logging.getLogger() logger.setLevel(logging.DEBUG) # encodingを指定しないと、Windowsではshift-jisで出力される # delay=Trueを指定し、初書込み時にファイルを作成するようにする file_handler = logging.FileHandler(file_name="hoge.log", encoding="utf-8", delay=True) file_handler.setLevel(logging.DEBUG) formatter_file = logging.Formatter("{levelname:<5}| {message}", style="{") # logging.info(), logging.debug()などを呼んだ回数がcapacityを上回った場合、targetに出力される # capacityは場合によっては1000とかの方がよいかも # flushLevelは高めに設定 file_handler.setFormatter(formatter_file) memory_handler = MemoryHandler( capacity=100, flushLevel=logging.ERROR, target=file_handler ) logger.addHandler(memory_handler)
上記2つを用いた、擬似シミュレーションのコードは次の通り。
パラメータはtoml形式で以下のように設定した。
[global] description = "ノミナルケース" max_timestep = 3 param = 0
標準出力には以下のように出力される。
ノミナルケース @ 2019/12/31 12:52:24 iter: 0 iter: 1 iter: 2 100%|███| 3/3 [00:00<00:00, 4.70it/s] ------ Final Results ------ Elapsed time: 00:00:0.6 ---------------------------
ログファイルへの出力は以下の通り。
INFO | ノミナルケース @ 2019/12/31 12:52:24 DEBUG| Args: ['c:/Users/thund/Desktop/test/src/logging-test.py'] INFO | iter: 0 INFO | iter: 1 INFO | iter: 2 INFO | ------ Final Results ------ INFO | Elapsed time: 00:00:0.6 INFO | --------------------------- DEBUG| ------ Parameters ------ DEBUG| [global] DEBUG| description = "ノミナルケース" DEBUG| max_timestep = 3 DEBUG| param = 0 DEBUG| ------------------------
