見出し画像

TWLogAIAN:Apacheアクセスログ分析の裏技を組み込むために早起きした

twsnmp

今朝は３時半に起きました。昨日寝る時に思いついたアイデアを組込みたくて早く目が覚めました。
よく利用されているWEBサーバーApacheのアクセスログはHTTPのリクエストを受信した時刻をタイムスタンプとして記録しますがログファイルに書き込むのは応答を送信した後です。このため複数のリクエストを受信した場合に処理が遅れたリクエストのログはタイムスタンプが逆転している場合があります。

211.73.79.25 - - [19/Feb/2022:17:59:20 +0900] "GET / HTTP/1.0" 200 9915 "http://www.twise.co.jp" "Mozilla/5.0 (X11; Linux i686 on x86_64; rv:51.0) Gecko/20100101 Firefox/51.0"
131.220.6.152 - - [19/Feb/2022:17:59:10 +0900] "GET / HTTP/1.0" 200 14345 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.79 Safari/537.36"

のようなケースです。この例では２行目のログが１行目の１０秒前です。この１０秒はWEBサーバーが応答を返すためにの処理にかかった時間を示すことがあります。データベースなどに読み込んで時刻順に並べてしまうと、この情報は見えなくなってしまいます。ログ・ファイルの状態でのみ存在する情報です。前からこの情報を取得する方法をいろいろ考えていました。最初は読み込む時に行番号を記録しておき行番号順に並べた時に時刻が逆転するケースを調べる方法を考えていました。しかし、昨日寝る前に、より簡単でにできる良いアイデアを思いつきました。
前のログのタイムスタンプとの差分を記録すればよいというものです。
これを作る前に、まず時系列のデータをグラフ表示する機能を作りました。

時系列データのグラフ表示

ついでなので、TWSNMP　FCのディスク使用量の線形予測も移植しました。

線形予測

作ってはみましたが、たぶん計算が間違っています。後で修正しようと思います。
この開発は、

です。これでレポート機能は一段落しようと思います。
本題の前のログとの時間差の組み込んでみました。

前のログとの時間差

思った通り、処理が遅延したところはマイナスの値（黄色の矢印）になっています。そして予想していなかった情報が取得できました。緑の矢印の部分
と

前のログとの時間差

の赤い矢印の部分です。これは、５分毎の定期処理のアクセスを表しています。
TWLogAIANを実務で使いはじめていますが、かなり便利です。

次の開発は検索結果やレポートをCSVやEXCELにエクスポートする機能を考えていますが、今日はここまでです。

明日に続く


開発のための諸経費（機材、Appleの開発者、サーバー運用）に利用します。 ソフトウェアのマニュアルをnoteの記事で提供しています。 サポートによりnoteの運営にも貢献できるのでよろしくお願います。