情シスは何度でも甦るさ。

OracleDB/Ruby好きの情シス部員がお送りします

iisのアクセスログのtimeって開始時間か終了時間か?

ASP.NET Webforms アプリがあるのだが、このごろピーク時の性能劣化がひどくなってるとのことで、Zabbixでリソース監視したり、アクセスログなんかをBigQueryに突っ込んで原因を探ったりしていたのだが、iisのログのtime って、そもそも開始時間なのか、処理の終了時間なのかが気になった。

iisのログには、time-taken という処理時間(ミリ秒)が出力されるが、timeが、開始時間なのか、終了時間なのかでログの見方は変わってくる。

microsoftのサイトを見ると

要求が発生した時刻です。協定世界時 (UTC) で表示されます。

とあるので、リクエストの開始時刻と思われるが、なんか腑に落ちないのでテストしてみた。

環境

OS:Windows2012R2 サーバ
iisバージョン:8.5
ログ形式 :W3C

テスト方法

1.めっちゃ重いタイムアウトになる処理を投げる

2.アクセスログでどう記録されるか確認する。

今回は、17:10に処理を開始し、17:31にタイムアウトが発生した。

で、結果。

time:17:31

処理が終わった時間やん!

設定でここの挙動変えれるの?

というわけで、ちょっとハマった話。