Groovyでログから特定区間の処理時間を計算する

Groovy ag

障害調査とかログから処理時間を抽出するというのをごにょっとやったのでメモを残しておきます。(書いとかないと絶対忘れるやつだし)

ログファイルから欲しい情報を抜き出す

スタックトレースを起点に処理時間を抽出しようとするとその行には日付などの情報が入って無くて前後数行欲しいってありますよね。

$ ag --nonumbers -B4 -A1 -G "hogehoge.log*" "^System\.Data\.SqlClient\.SqlException"
  • -B4 は前4行を抜き出すということです
  • -A1 は後1行を抜き出すということです
  • -G で正規表現を使うようにしてます

2点間の処理時間を調べる

上で抽出した中間ファイルからExcelで処理するようのCSVを作成します。
使い慣れたGroovyでやってみます。使い捨てのスクリプトなので適当に書いてます。

  • 取り敢えず半角スペースでsplitしながらぐるぐる回します
new File('hogehoge.txt').splitEachLine(' ') { logs ->
    // 処理
}
  • 上の処理の中身(回しながら欲しい2点間のログを抽出)
    def format = "yyyy-MM-dd HH:mm:ss,SSS"

    comment = logs[7]
    if (!comment) {
        //println "null"
    }
    else if (comment.contains("アプリケーションを開始")) {
        start = new Date().parse(format, "${logs[3]} ${logs[4]}")
    }
    else if (comment.contains("DBの接続に失敗しました")) {
        end = new Date().parse(format, "${logs[3]} ${logs[4]}")
        time = end.toTimestamp().getTime() - start.toTimestamp().getTime()
        println "${logs[0]}\t${logs[3]} ${logs[4]}\t${time}"
    }

logs[7]にログの文字列が入ってくる想定なので計測したい2点間のキーワードを引っ掛けて、ログの時間を取得して処理時間を計算します。
この時に、.NETのlog4netで出している形式をformatで定義してData().parseで変換してます。
yyyy-MM-dd HH:mm:ss,SSS こんな形式で実際には2017-01-16 12:34:56,789って感じのやつですね。
timeに処理時間を入れてます。計算するときは、toTimestamp().getTime()を使ってミリ秒単位で結果が出るようにしています。

って言うか、最初からログに処理時間を出すようにして欲しいデス！！！

おまけ

  • ログが巨大なのでちょっと1万行くらい処理して様子をみたいとかあるのですが、Groovyのeachの中ではbreak出来ないので無理やり抜けるようにしてました。
def i = 0
new File('hogehoge.txt').splitEachLine(' ') { logs ->
    // 処理
    i++
    if (i > 10000) { System.exit(0) }
}

他にいいやり方があれば教えて欲しい・・・。

  • 一応、ソース付けておきます。
def i = 0
def format = "yyyy-MM-dd HH:mm:ss,SSS"
def start
def end
def time
def comment

new File('hogehoge.txt').splitEachLine(' ') { logs ->
    comment = logs[7]
    if (!comment) {
        //println "null"
    }
    else if (comment.contains("アプリケーションを開始")) {
        start = new Date().parse(format, "${logs[3]} ${logs[4]}")
    }
    else if (comment.contains("DBの接続に失敗しました")) {
        end = new Date().parse(format, "${logs[3]} ${logs[4]}")
        time = end.toTimestamp().getTime() - start.toTimestamp().getTime()
        println "${logs[0]}\t${logs[3]} ${logs[4]}\t${time}"
    }
    // 1万行ほどやってみるときは下のコメントを外す
    //i++
    //if (i > 10000) { System.exit(0) }
}