Zabbix単体でログからアバウトなレスポンスタイム計測

背景

色々な仕組みが混在したシステムでボトルネックとなっている機能を特定するのに手間がかかりすぎる問題に対して、ログの中身を見てボトルネックを特定することが多々あった。大概問題が起きている機能はレスポンスタイムが遅くなっていたり、実行回数が異常であったりする。それを確認するためにいちいちログファイルを見て集計するのが面倒であったため、何か簡単にできる方法はないかと考えたもの。

概要

Zabbix単体でログからレスポンスタイムを計測する。具体的に取得するデータは単位時間(1監視間隔)当たりの以下。ログの時間をログ監視で取得し、計算アイテムで集計する。

• 平均応答時間
• 最大応答時間
• アクセス回数

ただし、以下の欠点がある。

• 単位時間内にアクセスが無い(つまりログが無い)場合、その後のデータが正しく取得できない。Zabbixの平均値や最大値取得の関数がデータが0であると首都負荷状態になるため。「取得不可アイテムの監視間隔」後に正常に取得し出すが抜けた分は取得されない。
• 単位時間はログに記載された時間ではなく、もととなるデータをZabbixがログ監視で取得したタイミング。
• ログ監視と計算のタイミングが被ると集計がおかしくなる。

導入してみた結果、上記欠点が分かったためfluentdとZabbixで同様のデータを取得をしたいと考えた。しかしながら、精密なパフォーマンス取得ではなくボトルネック特定程度の用途であれば耐えれそう且つ、導入が容易であるため記事にしました。

構築方法

0. Apacheでレスポンスタイムを表示

Apacheを例にレスポンスタイムを測定する。デフォルトではレスポンスタイムが出力されないため、以下の設定をする。

• 設定内容

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
LogFormat "%h %l %u %t \"%r\" %>s %b" common

## 上記の付近に以下を追加
LogFormat "time:%{%Y/%m/%d_%H:%M:%S %z}t\tx_forwarded_for:%{X-Forwarded-For}i\tremote_host:%h\trequest:%r\tlast_status:%s\tsize:%b\treferer:%{Referer}i\tuser_agent:%{User-Agent}i\tv_host:%{Host}i\tresponse_time:%D" apache_ltsv

## 以下をコメントアウト
#CustomLog "logs/access_log" combined

## 上記の付近に以下を追加
CustomLog "logs/access_log" apache_ltsv

• 出力例

time:2020/03/08_12:35:59 +0900  x_forwarded_for:-       remote_host:xxx.xxx.xxx.xxx        request:POST /zabbix/jsrpc.php?output=json-rpc HTTP/1.1    last_status:200 size:63 referer:http://xxxxxx/zabbix/zabbix.php?action=dashboard.view  user_agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.132 Safari/537.36     v_host:xxxxxx       response_time:35108

1. Zabbixでログ監視アイテム設定

監視間隔は短めにする。パフォーマンスデータを1分間隔で取得したいのであれば次項の計算アイテムを1分間隔に設定するのであるが、それより短いほうがいい。このアイテムと次項のアイテムの取得間隔を同じにした場合、取得タイミングが秒単位でかぶると計算アイテムが正しい値を取得しなかった。
また、いくつかのZabbixのバージョンで試したが、データ型がおかしいエラーが出たときは数値(浮動小数点)で実施するととれることがある。

・名前: (任意)
・タイプ: Zabbixエージェント(アクティブ)
・キー: log[/var/log/httpd/access_log,"items\.php.*response_time:([0-9]+)$",,,,\1]
・データ型: 数値(整数)
・監視間隔: 15s (短め、負荷を考えないのであれば1sでいい)  

2. 計算アイテムの設定

アクセス回数

上記で作ったアイテムに"などが含まれるときは式内でエスケープが必要になるので気を付ける。

- 名前: Log_ApacheResponseTime_COUNT (任意)
- タイプ: 計算
- キー: ApacheResponseTime.COUNT (任意)
- 式: count("log[/var/log/httpd/access_log,\"items\.php.*response_time:([0-9]+)$\",,,,\1]",30)
- データ型: 数値(整数)
- 回
- 監視間隔: 30s

平均値

1000000で割っているのはApacheでログに出力しているレスポンスタイムがマイクロ秒であるため。

- 名前: Log_ApacheResponseTime_AVG (任意)
- タイプ: 計算
- キー: ApacheResponseTime.AVG (任意)
- 式: avg("log[/var/log/httpd/access_log,\"items\.php.*response_time:([0-9]+)$\",,,,\1]",30)/1000000
- データ型: 数値(浮動小数点)
- 単位:秒
- 監視間隔: 30s

最大値

- 名前: Log_ApacheResponseTime_MAX (任意)
- タイプ: 計算
- キー: ApacheResponseTime.MAX (任意)
- 式: max("log[/var/log/httpd/access_log,\"items\.php.*response_time:([0-9]+)$\",,,,\1]",30)/1000000
- データ型: 数値(浮動小数点)
- 単位:秒
- 監視間隔: 30s