ログから処理時間を出力するスクリプトを書いてみた

実現したいこと

下記のようなログから処理にかかった時間（ミリ秒）を計測してファイルに出力する。

ログ（記録日 記録時刻 ホスト名 スレッドID レベル カテゴリ メッセージ）
2018/05/02 13:05:42.446 host01 [1] INFO  Category Start_Job
2018/05/02 13:05:42.537 host01 [1] INFO  Category End_Job

出力結果（ジョブ開始時刻 メッセージ1, ジョブ終了時刻 メッセージ1, かかった時間
08:57:00.323 Start_Job,08:57:00.745 End_Job,422

背景

開発している製品で現場から障害報告とともにログが送られてきた。内容を見てみると、ある処理で非常に時間がかかっていることが分かった。
間欠的に発生しているようだが、発生個所をいちいち目視で確認するのはたいへんなので自動的に調べるようにしたいと思った。

プラットフォームはWindowsなのでPowerShellが第一候補だったが、Creators Updateでbashがサポートされたという情報を聞いていたので、勉強を兼ねてbashで書いてみようと思った。

環境

• OS：Windows 10
• Unix動作環境：CygWin
  ※WSL は環境構築が面倒くさそうだったのでCygWinを使うことにした。いずれは試してみたい。

スクリプト

bash初心者なので、非常にしょぼい内容になっているがご容赦ください。
一時ファイル作成で列区切をスペースにすれば、もっと簡潔なプログラムにできた気がする。
また、grepする文字列も引数で渡せるようにすればよかった。

#!/bin/bash

## ##を二つ並べたコメントは学習用のコメント(for me)
## 最初の行は bashを使うと宣言

# usage 関数
## ${0}はコマンド引数の0番目になる。eg. ./detect_proc_time.sh
## basename でファイル名だけ取り出している。detect_proc_time.sh
function usage {
  cat <<EOF
$(basename ${0}) is a tool for detecting processing time.

Usage:
  $(basename ${0}) 'InputFile OutputFile <threashold_ms>'

Args:
  InputFile:targe file
  OutputFile:output file
  threashold_ms:a processing time longer than this, then output.(msec, default=0)
Example:
  $(basename ${0}) './Log/20180425.log Output.txt 1000'
EOF
}

# entry
## $#はコマンド引数の個数
if [ $# -lt 2 ]; then
  usage
  exit 0
fi

## ${3}は3番目のコマンド引数
threshold_ms=0
if [[ ${3} -gt 0 ]]; then
  threshold_ms=${3}
fi

# 指定文字列が存在する行を一時ファイルに出力する
## ファイルから指定文字列の行を抜き出し、2列目と7列目を出力する(awk '/Start_Job/ || /End_Job/ {print $2, $7}' $1)
## Unix改行に変える(tr -d '\r')
## 2行を1行にまとめる(awk '{if(NR%2)ORS=",";else ORS="\n";print}')
awk '/Start_Job/ || /End_Job/ {print $2, $7}' $1 | tr -d '\r'  | awk '{if(NR%2)ORS=",";else ORS="\n";print}' > temp.txt

## 組み込みコマンド':'(何もしない)を使って、結果ファイルの中身をクリアする
offset_file=${2}
: > $offset_file

# 処理時間を出力する
cat temp.txt | while read line; do
  #echo $line

  #先処理の時刻を検出
  ##先頭から12この数字を切り出す(${line:0:12})
  tm=${line:0:12}
  time1=`expr ${tm:0:2} \* 3600000 \+ ${tm:3:2} \* 60000 \+ ${tm:6:2}  \* 1000 \+ ${tm:9:3} `

  #後処理の時刻を検出
  ##40桁から12この数字を切り出す(${line:0:12})
  tm=${line:40:12}
  time2=`expr ${tm:0:2} \* 3600000 \+ ${tm:3:2} \* 60000 \+ ${tm:6:2}  \* 1000 \+ ${tm:9:3} `

  ##expr は文字列から数値に変換するコマンド。
  ## 四則演算の前に\を付けることで演算子と認識する。
  time_offset=`expr $time2 \- $time1`
  echo 'time_offset =' $time_offset
  if [ $time_offset -lt $threshold_ms ]; then 
    continue
  fi

  echo $line','$time_offset >> $offset_file
done

# 一時ファイルの後始末
rm temp.txt

その他

• Cygwin内でDドライブに移動する方法
  cd /cygdrive/d