PowershellでWEBサーバのアクセスログ統計1

Awk好き技術者の書いたPowerShell

背景

　Windows環境で開発をしていると「こんなのUnix環境だったらスクリプトを書いてすぐなのになぁ。。」ってなことが時々あります。MS系OSもバッチ,WSH,PowerShellと変わってきて、PowerShell3.0では性能も相当改善されるので今後はいわゆるスクリプト言語として適用される場面も増えそうな気配がします。(ほんとうにyet another script languageですね!!)
　私はこれまでPowerShellをバッチファイルの代わりにしか使用していませんでしたが、今回はもっとUnix的な考え方で使ってみることにしました。
たまたま最近IISのアクセスログ統計を作る機会があったのですが、その際はcygwin+bash+gawk+sedで終わらせてしまいました。今回はその雛形部分をPowerShell2.0で作ってみました。

お題

IISのアクセスログからPV数をカウントする。画像ファイルやHTTPの戻りステータスが200だけを対象とする。結果は日本標準時の日付別で表示する。

bashとawkでいつもやっているパイプライン処理はなるべく変えない。

パフォーマンスはあまり期待しない。でも極力優先する。

$yesterday=(Get-Date).addDays(-1).ToString("yyMMdd") 
$yesterdayMonth=(Get-Date).addDays(-1).ToString("yyMM") 
$inputFiles=".\input\u_ex"+$yesterday+".log"  #IISのログファイルを指定する（ここでは昨日データ）

#入力するアクセスログファイルのカラム名を配列として定義する。
$fields=
-split ("DATE TIME SV_NAME SV_IP METHOD URL_STEM URL_QUERY PORT USERNAME CL_IP U_AGENT HOST " + 
"STATUS SUB_STATUS WIN32_STATUS TIME_TAKEN" )

#カラム名の配列の逆引き用に連想配列を定義する。（"SV_IP"→配列番号3みたいに。）
$fieldIndex = $fields |% -begin{$i=0;$h=@{}} {$h.$_=$i++} -end{$h}

#日時分秒を日本標準時に変換 
function ConvertTo-JST
{
    Process{
        $col=$_.split()
        $newDateTime=-split (Get-Date ($col[$fieldIndex.DATE] + " " + $col[$fieldIndex.TIME])).addHours(9).ToString('yyyy/MM/dd HH:mm:ss')
        $col[$fieldIndex.DATE]=$newDateTime[0]
        $col[$fieldIndex.TIME]=$newDateTime[1]
        $col -join " "
    }
}

#アクセスログからパラメータ指定されたカラムのみを選択し空白区切りの文字列として返す
function Select-Columns
{
    Begin{
        for ($i=0; $i -lt $args.length; $i++){
            if ( $fieldIndex[$args[$i]] -eq $null ){
                 #ここでパラメータチェックする（未実装）異常終了ってどうするの？
            }
        }
    }
    Process{
        $cols=$_.split();$new_cols=@()
        for ($i=0; $i -lt $args.length; $i++){$new_cols += $cols[$fieldIndex[$args[$i]]]}
        $new_cols -join " "
    }
}

#同一文字列でカウントし、結果を新しいカラムとして追加
function Add-Counter
{
    Begin{
        $count=@{}
    }
    Process{
        $count[$_] ++
    }
    End{
        foreach ( $key in $count.Keys){
            $key + " " + $count[$key]
        }
    }
}

#日別PV数レポート作成
function Out-Report1()
{
    $outputFile=".\report\SAMPLE_REP1_DAILY_PV_" + $yesterdayMonth + ".txt"
    (Get-Date).ToString() + " " + $outputFile
    
    #cat $inputFiles -ReadCount 1000|% {$_}| #１回あたりの読み込み件数を増やすと約10%早くなった
    cat $inputFiles |
        ? {$_.split().length -eq $fields.length}| #カラム数が合わない行は取り除く
        ? {$_.split()[$fieldIndex.URL_STEM] -notmatch ".*\.(gif|jpg|png|css|js)$"}| #抽出条件：画像ファイルやcss,js以外
        ? {$_.split()[$fieldIndex.STATUS] -match "^200$"}| #抽出条件：STATUS OKだけ
        ConvertTo-JST| #日時分秒を日本標準時に変換 
        Select-Columns "HOST" "PORT" "DATE" | #レポート対象項目の選択
        Add-Counter| #同一行で集計しカウンター(COUNT)を追加
        sort >>$outputFile
}

(Get-Date).ToString() + " Start"
Out-Report1 #日別PV総数
(Get-Date).ToString() + " Finished!"

ちょっとだけ解説

ログファイルのフォーマット定義は最初の部分でグローバル変数$fieldsと$fieldIndexでやっている。

統計のメイン処理は関数Out-Report1でパイプ処理でやっている。

やってみてわかったこと

【良かったこと】

若干表記の違いはあるけど、shellスクリプトの気持ちで書けた。PowerShellの流儀としてはログフォーマット定義はグローバル変数でなく、オブジェクトのプロパティ(Set-MemberでNotePropertyでやる）の方が自然なんでしょうが、やってみたらとんでもなく遅くなり結果的にベタな文字列処理になったのが少し不満なところです。でも、連想配列、配列、Begin、End、パターンマッチングなどはが自然にあり、楽しかったです。はい。

枠組みとしてはできたので、ちょっと直せば以下の様な色々なパターンの統計もできますね。（実際にいくつかやりましたが、あまりこらなければどれも簡単）

1. PV数の多いページのURLとそのアクセス回数
2. 時間帯別や曜日別のPV数
3. HTTTPStatusが400番台だったページの多かったものを表示（リンク修正漏れチェックなどで使用）
4. 一日あたりのユニークユーザ数（クライアントIPやUSERNAMEから判断）
5. ページ別のレスポンス時間（平均、最大、最小、標準偏差）
6. PV数が多いブラウザの種類とバージョン（UserAgentで判断）
7. PV数が多いOSの種類とバージョン（UserAgentで判断）

【改善すべき点】

レスポンス性能がとても悪い。

• 環境としては２年ほど前に購入したXeon E5506@2.13GHz ☓２コア、メモリ２GB、WindowsServer2008 SP1 (32bit)でやりましたが、結果は以下のとおり。
入力ファイルサイズ150MB(55万件）　→　処理にかかった時間3分40秒 ※Cygwin+bash+gawkでやったら10倍以上早かった。
• 根本的原因はどうもGet-Content(=cat)の処理が遅いことパイプライン処理でのオブジェクトの引渡しが遅いことと文字列をsplitして判断していることのようで改善は難しいのですが、統計処理の初期データを作成するところを別にしてやり、不要データの削除（および、ブラウザやOSの種別の判断など）を事前にやっておけば、数十秒の応答時間になりそうです。事前処理はGet-Contentの-waitパラメータを使って、バックグラウンドジョブとしてリアルタイムに事前処理をやることもできます。（これはこれでおもしろそうですね。ジョブは他のマシンで動作させることもできるので複数台のWEBサーバで同時に動かすことも可能です。）
• Windows8に搭載される予定のPowerShell3.0ではパフォーマンスは格段に良くなっているのでそちらにも期待しましょう。

グローバル変数の扱いが悩ましい。

• ログファイルのフォーマットをグローバルスクリプトスコープの変数に格納しましたが、実際の統計処理のパイプラインの流れの中では表示項目を絞ったり、カウンタを追加したりして、フォーマットは変化します。Set-Memberでやればオブジェクトの属性としてもたせられるのですが、パフォーマンスが悪いのでそれも難しい。なにか他にいいやり方がないか思考中です。

　ま、個人的にいうと数万件以上のデータに対する逐次処理である程度の処理性能（数秒とか数分とか）を求めるのであれば、PowerShell2を何も考えずに使うのは今のところ少し厳しいかなという感じです。ただし、せっかく面白い機能が色々とあり、PS3での性能改善のこともあるので余裕があったら今のうちに色々と遊んでおくのは良いかなと思います。パイプライン処理は40年？も前から実装されている機能ですが、マルチコア環境の分散処理に向いていたりして今後もまだ有望な処理方式です。将来はパイプライン処理を使ってオンライン業務を構築する日なんかも来るかもしれませんしね。

関連ページ

　パイプライン処理の時間計測で単純な文字列のパイプライン処理時間計測をやりましたので参考まで。
　パイプライン処理の並列性でパイプライン処理が並列に処理されていない（ことがある）ことを書きました。