機械学習（深層学習）の開発では，一般的なプログラミングでの開発とは異なり，実行から結果の確認までのフィードバックまでの時間がとても長いです．機械学習初心者の私はその違いをあまり深く認識しておらず，当初はその特性の違いで困っていました．失敗をしていく上で，このやり方でログをまとめると便利だなと思うTipsが溜まったので共有したいと思います．師匠や長年機械学習をやってきたわけではないので，何を当たり前な．．みたいなことを思う方もいらっしゃるかもしれませんが，あしからず．機械学習系のブログは理論解説が多く，実践的な開発ノウハウが少ない気がするので，これを機にこういうエントリが増えたらと思います．こういうやり方も便利だよ，というのがありましたら是非コメント欄にてフィードバック頂けると幸いです．
なお今回の話は，ポッドキャストのrebuild.fmでのhigeponさんの回に深く同意する内容になっています．
Rebuild: 208: Oculus Go On The Go (higepon)
ロガーの準備
pythonを前提にする場合は，私はいつも下記のような形で使ってます．ファイル名は基本的にタイムスタンプにしていて，必要に応じて実行時引数でログファイル名を指定しています．
import logging import argparse parser = argparse.ArgumentParser() parser.add_argument('--log', type=str, help='Specify a logger\'s output filename') date_label = datetime.datetime.now().strftime('%Y%m%d-%H%M%S') log_fname = args.log if args.log is not None else 'logs/{}.log'.format(date_label) logging.basicConfig(level=logging.DEBUG, filename=log_fname, format='%(asctime)s %(message)s', datefmt='%Y%m%d-%H%M%S') console = logging.StreamHandler() console.setLevel(logging.DEBUG) formatter = logging.Formatter('%(message)s') console.setFormatter(formatter) logging.getLogger('').addHandler(console) log = logging.getLogger(__name__) log.info('log file: {}'.format(log_fname))
引数一覧はログに出力する
深層学習の開発ではいろいろとモデルをカスタムしていく上で，様々な実行時引数を取るようにカスタムする傾向にあると思います．そこで私は実行時には下記のようにして実行時引数（指定しなかった場合はデフォルトの引数も）をログに残しておくようにします．これにより，隠れ層の次元数を引数でしているけど何を指定したっけな．．みたいなことがなくなります．
for arg in vars(args): log.info('Arg: {}={}'.format(arg, getattr(args, arg)))
20180630-000951 log file: logs/20180630-000951.log 20180630-000951 Arg: batch_size=32 20180630-000951 Arg: n_epochs=25 ...
実行時引数を利用してメモを残しておく
実行時引数を利用してメモを取れるようにしておきます．プログラム実行には時間がかかるので，何か目的があって実行したプログラムのはずなのに，なんでこれ動かしたんだっけ．．みたいなことが防げます．
parser.add_argument('--note', type=str, help='Note for this running.')
$ python train_model.py --note "OptimizerをSGDからAdamに変更してみた"
Gitのリビジョン番号をログに残す
プログラムは常に更新していると思います．そのため私はこまめにコミットをしているのですが，ログにも実行時のリビジョン番号をしっかりと残しておくと，あとあと自分の結果の再現をするときに便利です．ただ毎度コミットした状態で実行するとは限らないので，先程の"note"ハックとセットで使うと便利です．
import subprocess rev = subprocess.check_output(['git', 'describe', '--always']).strip().decode('utf-8') log.info('Git rev: {}'.format(rev))
Git rev: 33c55c9
実行時間は計算しておく
深層学習の実行は時間がかかるので夜中とかに回しとくことが多いです．そのためどれぐらい実行に時間がかかるかを残しておくことは，作業時間の見積もりに対して有用です．
import time begin_time = time.time() # .... # プログラムの最後 log.info('Process time: {:.3f}h'.format((time.time() - begin_time)/3600))
実行完了時のログは整理した情報を出力し，Evernoteなどにコピペできるようにする．
実行完了後，実行結果を要約してレポートを出力するようにします．私はEvernoteを使っていて，この最後のレポートをEvernoteにコピペするようにしています．Evernoteなどのメモソフトにこのようなレポートをコピペしておけば，また後日このコピペ内容からログファイルを見たりするのが容易です．例えば，このパワポで進捗報告した82.476%の性能って，どの段階でで出たんだっけ？みたいなときにEvernoteで検索するとこれがヒットします．もちろんそのためにはEvernoteのノートのタイトルや，メモを残しておいた方が（自分に）親切です．
20180630-022147 -----Final Report. Running mode: 3 ------ 20180630-022147 Hoge1 Acc : 82.476% 20180630-022147 Hoge2 Acc : 71.46% 20180630-022147 log file: logs/20180630-000951.log 20180630-022147 python train_my_model.py --mode 3 --resume ckpts/hoge1.model --note "MLPのレイヤ数を3に増やしてみる" 20180630-022147 Git rev: 9ac7188 20180630-022147 Process time: 3.5h
- MLPのレイヤ数を３に増やして，性能向上を試みる // ここに先程のログをコピペ
ログはfilterを通して閲覧する
ログは漏れがあるといけないので基本的に冗長に出力するケースが多いと思います．そのため出力されたログから迅速に必要な情報をフィルターする必要があります．私はpecoを使っています．これはlessなどとパイプで組み合わせて，該当行を高速に表示してくれます．リンク先に動作gifがあるのでご参考に．
less logs/my_log.txt | peco
また私はログファイルがタイムスタンプになっていて探るのが面倒なので，あるディレクトリ下の最新のログファイルをtailとpecoで読み取るスクリプトを利用しています．リアルタイムログ閲覧＋pecoにより，決まったログだけを眺めることができて経過を見守れます．
#!/bin/sh ls -t logs/* | head -1 | xargs tail -f -n+1 | peco
と雑多に書いてみましたがこんな感じです．ログは面倒ですが，人の記憶は適当なものなので，たった数分前の自分がやったことも理解できなかったりします．こういったログTipsが他にも増えたらと思います．
次回は需要があれば，pudbによるリモート開発Tipsをできたらと思います．
