chainerの学習ログをSlackに垂れ流す

バックグラウンドジョブでChainerに投げた学習のログを、
出先でも確認できるようにSlackに垂れ流させるようにしました。
特に目新しいものはないと思いますが、色々とハマった部分があったのでメモ程度に残します。

環境

chainer (2.0.0)
Ubuntu 16.04.3 LTS (Xenial Xerus)

結果

経緯は省いて先に最終結果を

• chainerの学習(バックグラウンド実行)
  • out.logに結果を書き出します

$ nohup python train.py --gpu 0 .... > ~/out.log 2> ~/err.log < /dev/null &

• slack通知ジョブ

$ nohup tailf ~/out.log | egrep -v "%|epochs|finish" | sed -e "s/\x1B\[4A//g" -e "s/\x1B\[J//g" | ~/cat_slack.sh &

• cat_slack.sh
  • curlでslackのincoming webhooksに投げます
  • [10分で出来る]シェルスクリプトの結果をslackに投稿を参考にしました

while read LINE;
do
    RAW_MESSAGE=$LINE
    if [ -p /dev/stdin ] ; then
        # 空行チェック
        if [ -z "$RAW_MESSAGE" ]; then
            exit
        fi
        #改行コードをslack用に変換
        echo $RAW_MESSAGE | tr '\n' '\\' | sed 's/\\/\\n/g'  > ${MESSAGEFILE}
    else
        echo "nothing stdin"
        exit 1
    fi
    WEBMESSAGE='```'`cat ${MESSAGEFILE}`'```'
#Incoming WebHooks送信
    curl -s -S -X POST --data-urlencode "payload={\"channel\": \"${CHANNEL}\", \"username\": \"${BOTNAME}\", \"icon_emoji\": \"${FACEICON}\", \"text\": \"${MESSAGE}${WEBMESSAGE}\" }" ${WEBHOOKURL} >/dev/null
done

ハマったところ解説

chainerのログから必要部分の抽出

chainer.trainerは標準出力にきれいに整形したログを出力してくれます

epoch       main/loss   validation/main/loss  main/accuracy  validation/main/accuracy  elapsed_time
1           0.189549    0.103644              0.9419         0.9688                    31.0516       
     total [##................................................]  5.00%
this epoch [..................................................]  0.00%
       600 iter, 1 epoch / 20 epochs
    18.488 iters/sec. Estimated time to finish: 0:10:16.600328.

ところが、標準出力を流し込んだログファイルを見ると、
プログレスバーの表示や制御文字が邪魔となって必要なlossやaccuracyの情報を見つけるのが困難になっています。

epoch       main/loss   validation/main/loss  main/accuracy  validation/main/accuracy  elapsed_time
[J     total [..................................................]  0.83%
this epoch [########..........................................] 16.67%
       100 iter, 0 epoch / 20 epochs
       inf iters/sec. Estimated time to finish: 0:00:00.
[4A[J     total [..................................................]  1.67%
this epoch [################..................................] 33.33%
       200 iter, 0 epoch / 20 epochs
    17.136 iters/sec. Estimated time to finish: 0:11:28.624870.
[4A[J     total [#.................................................]  2.50%
this epoch [#########################.........................] 50.00%
       300 iter, 0 epoch / 20 epochs
    17.067 iters/sec. Estimated time to finish: 0:11:25.517683.
[4A[J     total [#.................................................]  3.33%
this epoch [#################################.................] 66.67%
       400 iter, 0 epoch / 20 epochs
    17.096 iters/sec. Estimated time to finish: 0:11:18.532756.
[4A[J     total [##................................................]  4.17%
this epoch [#########################################.........] 83.33%
       500 iter, 0 epoch / 20 epochs
    17.194 iters/sec. Estimated time to finish: 0:11:08.846695.
[4A[J1           0.192264    0.0928321             0.941417       0.9716                    36.0277       
[J     total [##................................................]  5.00%
this epoch [..................................................]  0.00%
       600 iter, 1 epoch / 20 epochs
    16.143 iters/sec. Estimated time to finish: 0:11:46.205764.

そこでgrepを使って必要なログ情報の絞り込み + sedコマンドで制御コマンドの置換を行います。

grepで絞り込み

プログレスバーの部分の表示は不必要なため、適当にgrepで消します

$ cat out.log | egrep -v "%|epochs|finish"

sedで制御文字の削除

ログファイルを見ると, ^[で始まる制御文字が各行の先頭に現れているので、これを削除します

参考 : シェルでASCII文字を扱う

cat out.log | egrep -v "%|epochs|finish" | sed -e "s/\x1B\[4A//g" -e "s/\x1B\[J//g"

これで制御文字の削除が行えるようになりました。

※ 制御文字の削除にcolというコマンドも見つけましたが、後述のバッファリングの問題に対応できなかったのでsedで消しました

ログの監視 + Slackへの通知

学習終了時ではなく、chainerのジョブがログを更新する度に通知をしてほしいので、
ログファイルの更新監視が必要になります。

そこで今回はtailfコマンドを利用しました
(tail -Fでもおなじことができるらしい(?))

tailf out.log

out.logが更新されるたびに更新部分のみを標準出力に出力してくれます。

前節のコマンドと合わせてみます。

tailf out.log | egrep -v "%|epochs|finish" | sed -e "s/\x1B\[4A//g" -e "s/\x1B\[J//g"

これで必要な情報のみが取り出せそうです。

ところが、実際にコマンドを叩いてみると
幾ら待てども何の出力も得られませんでした。

原因はgrepとsedにありました。

通常これらのコマンドは入力をバッファリングするため、リアルタイムに出力を得られません。

という訳で、引数を追加します。

tailf out.log | egrep --line-buffered -v "%|epochs|finish" | sed -u -e "s/\x1B\[4A//g" -e "s/\x1B\[J//g"

grepは--line-buffered, sedは-uでバッファリングを無効にし、行ごとに検索/置換をしてくれるようになります。

これでようやく必要な出力行が得られました。

epoch       iteration   main/loss   validation/main/loss  main/accuracy  validation/main/accuracy  lr        
0           100         5863.18     2204.52               0.0103125      0.0168842                 0.000308566  
0           200         2240.05     1783.37               0.018125       0.0255712                 0.000425853  
0           300         1506.67     1301.58               0.0346875      0.0190526                 0.000509208 

slackへの通知

あとはcurlでslackに通知を投げるだけです。

パイプ処理でも良さそうでしたが、こちら([10分で出来る]シェルスクリプトの結果をslackに投稿)の記事を参考に作成したシェルスクリプトで投げることにしました。

参考記事のスクリプトは行ごとの入力に対応していないので、
投稿部分を

while read LINE;
do
    # curlでPOSt処理
    ...
done

のように変更して完成です。

まとめ

学習の待ち時間にシェルスクリプトのお勉強ができました。

これで学外からアクセスできないPC上で学習を回しているときも安心です。