poller processの張り付きについて
お世話になっております。
Zabbixのpoller process busy率が張り付いたまま下がらない事象について、相談させて下さい。
環境、本事象の概要、発生経緯については以下の通りです。
## 環境
・AWS ECS (EC2 type) 上にインスタンスを1台構築
・zabbix-server-mysql, zabbix-web-nginx, grafana, data-volume, zabbix-agent その他のコンテナが動作
・AWS Optimized AMI t2.large
・Zabbix version: 4.0.1
・RDS MySQL version: 5.6
・Zabbixの情報
・稼働し始めて1年程度
・ホスト数(有効): 100
・アイテム数 (有効/無効/取得不可): 10252/1437/72
・トリガー数 (有効/無効): 3886/224
・1秒あたりの監視項目数(Zabbixサーバーの要求パフォーマンス): 160
## 概要
・import済のlibzbxpgsql templateを分割し、一部アイテムを無効化して再import。
・https://github.com/cavaliercoder/libzbxpgsql
・4日後にwindows os templateのLLDトリガーの閾値を手動で変更。
・https://github.com/zabbix/zabbix/blob/master/templates/classic/template_os_windows.xml
・さらにその4日後から、zabbix busy processの張り付きが発生、1ヶ月以上続く状態になった(現在も継続中)。
・ホスト側のCPUも上記プロセスにあわせ100%張り付きの状態。
・AWS ECS event log、MySQL slow query, error log等には特に関連するエラーやログは何も出ていない。
・zabbix-serverのsyslogには、housekeeperのプロセスが動作し不要なレコードを削除しているログが1週間後まで出ていたが、それ以外は出ていない。
## 本事象発生の経緯
・元々import済のllibzbxpgsql templateを複数templateへ分割し、一部アイテムを無効化して再importした。
・20の各ホストに5000以上のアイテムが紐付いていたが、100程度まで減らした。
・4日後にwindows os templateのLLD disk監視のトリガー閾値を変更 (40ホスト、80アイテム程度に影響)。
・その4日後からZabbixのpoller process、監視itemのqueueに異常が発生し始める。
・"Zabbix busy poller processes, in %"は5分毎に30%→100%を繰り返す。
・Zabbix queueに5000個程のアイテムが溜まる→捌けるを繰り返す。
・アイテム監視遅延は数十秒程度。
・"Zabbix busy history syncer processes, in %"が普段は10%(一定推移、MAX20%に瞬間で跳ねる程度)だが、30%まで上昇(MAX40%で、一定の推移)。
・"Values processed by Zabbix server per second"が普段は170程度だが、350まで瞬間的に跳ねる。
・housekeeperプロセスはlibzbxpgsql再import時よりずっと稼働していたが、1週間後には削除完了した模様。
・libzbxpgsqlのアイテムが20の各ホストに5000以上(100000アイテム以上)紐付いていたが、各ホスト100まで減らした為、アイテム、トリガー、各種ヒストリを削除していた。
・15日後、ホストをAutoScaleにより入れ替える。
・翌日から再びQueueが溜まり、CPUも逼迫し始める(上記と同じ状態に戻る)。
## dockerのリソース状況
NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS
zabbix-web-nginx 0.04% 80.21MiB / 7.79GiB 1.01% 193MB / 136MB 200MB / 115kB 0
zabbix-grafana 0.02% 27.67MiB / 7.79GiB 0.35% 65.2MB / 50.5MB 223MB / 14.4MB 0
zabbix-server-mysql 337.62% 159.6MiB / 7.79GiB 2.00% 19GB / 8.64GB 253MB / 5.73MB 0
zabbix-agent 1.51% 5.68MiB / 7.79GiB 0.07% 2.51MB / 2.17MB 56.1MB / 1.72MB 0
## docker inspects
一部抜粋。
[
{
"Args": [],
"State": {
"Status": "running",
"Running": true,
"Paused": false,
"Restarting": false,
"OOMKilled": false,
"Dead": false,
"ExitCode": 0,
"Error": "",
"Health": {
"Status": "healthy",
"FailingStreak": 0,
"HostConfig": {
"OomScoreAdj": 0,
"PidMode": "",
"Privileged": false,
"PublishAllPorts": false,
"ReadonlyRootfs": false,
"SecurityOpt": [],
"UTSMode": "",
"UsernsMode": "",
"ShmSize": 67108864,
"Runtime": "runc",
"ConsoleSize": [
0,
0
],
"Isolation": "",
"CpuShares": 256,
"Memory": 0,
"NanoCpus": 0,
"BlkioWeight": 0,
"BlkioWeightDevice": null,
"BlkioDeviceReadBps": null,
"BlkioDeviceWriteBps": null,
"BlkioDeviceReadIOps": null,
"BlkioDeviceWriteIOps": null,
"CpuPeriod": 0,
"CpuQuota": 0,
"CpuRealtimePeriod": 0,
"CpuRealtimeRuntime": 0,
"CpusetCpus": "",
"CpusetMems": "",
"Devices": null,
"DeviceCgroupRules": null,
"DiskQuota": 0,
"KernelMemory": 0,
"MemoryReservation": 268435456,
"MemorySwap": 0,
"MemorySwappiness": null,
"OomKillDisable": false,
"PidsLimit": 0,
"Ulimits": [
{
"Name": "nofile",
"Hard": 4096,
"Soft": 1024
}
],
"CpuCount": 0,
"CpuPercent": 0,
"IOMaximumIOps": 0,
"IOMaximumBandwidth": 0,
"Config": {
"Env": [
"ZBX_CACHEUPDATEFREQUENCY=60",
"ZBX_HISTORYCACHESIZE=16M",
"ZBX_TRAPPERTIMEOUT=300",
"ZBX_UNAVAILABLEDELAY=60",
"ZBX_DEBUGLEVEL=3",
"ZBX_ENABLE_SNMP_TRAPS=true",
"ZBX_STARTDBSYNCERS=4",
"ZBX_TIMEOUT=30",
"ZBX_VALUECACHESIZE=128M",
"ZBX_CACHESIZE=128M",
"ZBX_HISTORYINDEXCACHESIZE=4M",
"ZBX_TRENDCACHESIZE=128M",
"ZBX_UNREACHABLEPERIOD=45",
"TZ=Asia/Tokyo",
"ZBX_LOGSLOWQUERIES=3000",
"ZBX_SENDERFREQUENCY=30",
"ZBX_STARTPINGERS=5",
"ZBX_STARTPOLLERS=10",
"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",
"ZBX_VERSION=4.0.1",
]
}
}
]
## ホスト(EC2)のリソース状況
・CPU: 30→100を数分間隔で繰り返す
・memory: 8168820k total, 3317640k used, 4851180k free, 475096k buffers
・LA: 2~8
dstat
----system---- ---load-avg--- ------memory-usage----- -net/total- -dsk/total-
date/time | 1m 5m 15m | used buff cach free| recv send| read writ
19-05 19:41:44|2.71 4.81 5.04|1985M 464M 819M 4710M| 292k 394k| 0 0
19-05 19:41:45|2.71 4.81 5.04|1963M 464M 819M 4732M| 277k 304k| 0 488k
19-05 19:41:46|2.71 4.81 5.04|1997M 464M 819M 4697M| 558k 616k| 0 520k
19-05 19:41:47|2.71 4.81 5.04|1977M 464M 819M 4718M| 143k 175k| 0 0
19-05 19:41:48|2.71 4.81 5.04|1962M 464M 819M 4732M| 992k 1349k| 0 0
...
19-05 19:44:30|8.58 5.93 5.38|2004M 464M 819M 4690M| 328k 360k| 0 464k
19-05 19:44:31|8.58 5.93 5.38|2004M 464M 819M 4691M| 487k 595k| 0 0
19-05 19:44:32|8.58 5.93 5.38|1997M 464M 819M 4698M| 350k 444k| 0 936k
19-05 19:44:33|8.58 5.93 5.38|2031M 464M 819M 4663M| 268k 294k| 0 472k
19-05 19:44:34|8.58 5.93 5.38|2056M 464M 819M 4639M| 521k 778k| 0 0
zabbix_server process
/usr/sbin/zabbix_server --foreground -c /etc/zabbix/zabbix_server.conf
/usr/sbin/zabbix_server: configuration syncer [synced configuration in 0.377406 sec, idle 60 sec]
/usr/sbin/zabbix_server: alerter #1 [sent 0, failed 0 alerts, idle 337.961417 sec during 338.312448 sec]
/usr/sbin/zabbix_server: alerter #2 [sent 0, failed 0 alerts, idle 38.542574 sec during 38.888205 sec]
/usr/sbin/zabbix_server: alerter #3 [sent 0, failed 0 alerts, idle 638.931195 sec during 638.983966 sec]
/usr/sbin/zabbix_server: housekeeper [deleted 537357 hist/trends, 103512 items/triggers, 6 events, 0 sessions, 0 alarms, 0 audit items in 171.176304 sec, idle for 1 hour(s)]
/usr/sbin/zabbix_server: timer #1 [updated 0 hosts, suppressed 0 events in 0.010050 sec, idle 59 sec]
/usr/sbin/zabbix_server: http poller #1 [got 6 values in 0.210069 sec, idle 5 sec]
/usr/sbin/zabbix_server: discoverer #1 [processed 0 rules in 0.003130 sec, idle 60 sec]
/usr/sbin/zabbix_server: history syncer #1 [processed 150 values, 43 triggers in 0.281812 sec, syncing history]
/usr/sbin/zabbix_server: history syncer #2 [processed 0 values, 0 triggers in 0.000017 sec,idle 1 sec]
/usr/sbin/zabbix_server: history syncer #3 [processed 0 values, 1 triggers in 0.005900 sec,idle 1 sec]
/usr/sbin/zabbix_server: history syncer #4 [processed 0 values, 0 triggers in 0.000021 sec,idle 1 sec]
/usr/sbin/zabbix_server: escalator #1 [processed 0 escalations in 0.008354 sec, idle 3 sec]
/usr/sbin/zabbix_server: snmp trapper [processed data in 0.000021 sec, idle 1 sec]
/usr/sbin/zabbix_server: proxy poller #1 [exchanged data with 0 proxies in 0.000012 sec, idle 5 sec]
/usr/sbin/zabbix_server: self-monitoring [processed data in 0.000023 sec, idle 1 sec]
/usr/sbin/zabbix_server: task manager [processed 0 task(s) in 0.002815 sec, idle 5 sec]
/usr/sbin/zabbix_server: poller #1 [got 23 values in 0.285354 sec, getting values]
/usr/sbin/zabbix_server: poller #2 [got 0 values in 0.000014 sec, getting values]
/usr/sbin/zabbix_server: poller #3 [got 18 values in 0.258754 sec, getting values]
/usr/sbin/zabbix_server: poller #4 [got 15 values in 0.221686 sec, getting values]
/usr/sbin/zabbix_server: poller #5 [got 17 values in 0.275043 sec, getting values]
/usr/sbin/zabbix_server: poller #6 [got 40 values in 1.555246 sec, getting values]
/usr/sbin/zabbix_server: poller #7 [got 17 values in 0.278859 sec, getting values]
/usr/sbin/zabbix_server: poller #8 [got 17 values in 0.279526 sec, getting values]
/usr/sbin/zabbix_server: poller #9 [got 19 values in 0.288768 sec, getting values]
/usr/sbin/zabbix_server: poller #10 [got 16 values in 0.300415 sec, getting values]
/usr/sbin/zabbix_server: unreachable poller #1 [got 0 values in 0.000036 sec, idle 1 sec]
/usr/sbin/zabbix_server: trapper #1 [processed data in 0.000150 sec, waiting for connection]
/usr/sbin/zabbix_server: trapper #2 [processed data in 0.016266 sec, waiting for connection]
/usr/sbin/zabbix_server: trapper #3 [processed data in 0.000208 sec, waiting for connection]
/usr/sbin/zabbix_server: trapper #4 [processed data in 0.017421 sec, waiting for connection]
/usr/sbin/zabbix_server: trapper #5 [processed data in 0.018480 sec, waiting for connection]
/usr/sbin/zabbix_server: icmp pinger #1 [got 0 values in 0.000010 sec, idle 5 sec]
/usr/sbin/zabbix_server: icmp pinger #2 [got 0 values in 0.000011 sec, idle 5 sec]
/usr/sbin/zabbix_server: icmp pinger #3 [got 3 values in 2.016259 sec, idle 5 sec]
/usr/sbin/zabbix_server: icmp pinger #4 [got 0 values in 0.000011 sec, idle 5 sec]
/usr/sbin/zabbix_server: icmp pinger #5 [got 3 values in 2.018719 sec, idle 5 sec]
/usr/sbin/zabbix_server: alert manager #1 [sent 0, failed 0 alerts, idle 5.018167 sec during 5.018212 sec]
/usr/sbin/zabbix_server: preprocessing manager #1 [queued 0, processed 819 values, idle 5.094529 sec during 5.106248 sec]
/usr/sbin/zabbix_server: preprocessing worker #1 started
/usr/sbin/zabbix_server: preprocessing worker #2 started
/usr/sbin/zabbix_server: preprocessing worker #3 started
ランタイム待プロセス数は0~20(を繰り返している状況)です。
kernel modeのstackでI/O完了待ちプロセスを確認しようとしましたが、コンテナ内のproc/配下へroot userでアクセス出来ず、zabbix userへも切り替え不可だった為、調べられませんでした。
DB(slow, error, deadlock)、アプリ、ホスト、dockerのlogを見ても、関連するエラーやログは見当たりません。
ホスト、docker、DBのCPUやMemoryリソース、スペック等もimport前後で変更していません。
"StartPoller"のパラメータ値が現在10に設定してあり、256へ増やす等も検討したのですが、一時的な対応でしかなく根本原因を掴みたいです。
ホスト側のScale upも行ってみましたが、本事象は改善しませんでした。
zabbix-serverコンテナのpoller processが何らかアクティブハングアップ、スローダウンしているような状態かと思いますが、このような場合の調査、対応方法をご存知でしたらご教示いただけますと幸いです。
お手数ですが、よろしくお願い致します。
Yasumi - 投稿数: 372
参考になるか分かりませんが。。。
①DBのテーブル使用量は確認できますか?
②Zabbixの各Cacheの空き率も気になります。
③各poller processesの負荷率はどうでしょうか。
「元々import済のllibzbxpgsql templateを複数templateへ分割し、一部アイテムを無効化して再importした。」
上記によって、DBのテーブルに何らかの影響が出たのかもしれません。
肥大化していたり、Zabbixの各Cacheに影響が出ていないか確認してみてください。
各poller processesの負荷率ですが、下記のように数字を入れてアイテムを設定すれば
プロセスごとの負荷率の変化を確認できます。
zabbix[process,poller,1,busy]。。。etc
100%になっているので全体的に上がっているとは思いますが、
細かく確認してみるのもいいかもしれません。
hrk1l2x - 投稿数: 4
@yasumi 様
お返事遅くなりまして申し訳ございません, ありがとうございます.
> ①
テーブル使用量は以下の通りになります.
AWSのAuroraを利用しておりストレージは10GB毎に自動拡張される為, テーブル使用量は問題無いかなと思っています...
・Table size (計13GB程度)
・history_unit (6778MB)
・data: 4970
・index: 1808
・レコードとしては58904167ありますが、このサイズは特に異常でも無さそうですね...
・history_test (3043MB)
・data: 2845
・index: 198
・history (2295MB)
・data: 1709
・index: 586
・trends_unit (308MB)
・data: 308
・trends (91MB)
> 上記によって、DBのテーブルに何らかの影響が出た
ありがとうございます, 恐らくそうではないかなと思っていたのですが, 特に異常に肥大化しているテーブルがある等は無いようです.
> ②
Zabbixの各Cache空き率は添付の通りで, 余裕ありこちらも問題無いかなと思っています.
> ③
各Poller processの負荷率は添付の通り, 全体的に上がっている傾向にあります.
取り急ぎ共有まで.
TNK - 投稿数: 4671
StartPollersの値は10に設定されているようですが、秒間160アイ
テムの処理が必要であるならば、均一に分散されたとしても、1つ
のプロセスで、1秒間に16アイテムの値取得処理を行う必要があり
ます。
各アイテムの値を取得するために例えば、0.1秒かかるとしたら、
1秒間に10アイテムしか処理できないので、キューに溜まってしま
うこととなります。
実際には、アイテムの値取得時間を考慮して他のプロセスに振り分
けなおすということはなかったはずなので、偏りが発生していれば、
なおさらキューに溜まりやすくなるでしょう。
あと、アイテムの監視間隔のカスタマイズで、0分丁度とか特定の
時分に取得するような設定をしていた場合、そのタイミングに集中
するため、一度に処理できずにキューに溜まるという現象も発生し
やすくなると思われます。
監視するアイテム数や監視間隔を考慮して、Pollerのプロセス数を
少し増やすなどの調整を検討されてみてはいかがでしょうか?
hrk1l2x - 投稿数: 4
@TNK 様
お返事遅くなりまして申し訳ございません. コメントいただきありがとうございます.
Poller Processの処理数については次の通りです. 負荷が一番高い時には各process毎に最高100~300程度のアイテムを4秒~10秒程度でgettingしているようです.
zabbix 210 0.6 0.7 637972 59860 ? S 6月26 208:28 /usr/sbin/zabbix_server: poller #1 [got 245 values in 4.123104 sec, getting values]
zabbix 211 0.6 0.7 637920 59844 ? S 6月26 208:39 /usr/sbin/zabbix_server: poller #2 [got 238 values in 5.060744 sec, getting values]
zabbix 212 0.6 0.7 637920 59828 ? S 6月26 208:39 /usr/sbin/zabbix_server: poller #3 [got 131 values in 5.010963 sec, getting values]
zabbix 213 0.6 0.7 638020 60024 ? S 6月26 208:15 /usr/sbin/zabbix_server: poller #4 [got 295 values in 5.002502 sec, getting values]
zabbix 214 0.6 0.7 637932 59964 ? S 6月26 208:56 /usr/sbin/zabbix_server: poller #5 [got 205 values in 5.005141 sec, getting values]
zabbix 215 0.6 0.7 637920 59832 ? S 6月26 208:21 /usr/sbin/zabbix_server: poller #6 [got 182 values in 4.995484 sec, getting values]
zabbix 216 0.6 0.7 637984 59940 ? S 6月26 208:55 /usr/sbin/zabbix_server: poller #7 [got 297 values in 4.751103 sec, getting values]
zabbix 217 0.6 0.7 637932 59832 ? S 6月26 208:13 /usr/sbin/zabbix_server: poller #8 [got 333 values in 5.020236 sec, getting values]
zabbix 218 0.6 0.7 637972 59840 ? S 6月26 208:57 /usr/sbin/zabbix_server: poller #9 [got 239 values in 5.001394 sec, getting values]
zabbix 219 0.6 0.7 638008 59888 ? S 6月26 208:37 /usr/sbin/zabbix_server: poller #10 [got 239 values in 5.000449 sec, getting values]
秒間最高で60アイテムを処理する必要がありそうで, そうなると現在の10processから60process以上に上げる必要があるのかなと思っています. 検証してみます.
hrk1l2x - 投稿数: 4
また, 1アイテムの監視を何秒以内で完了すればPoller Processの遅延が無くなるか計算してみたのですが, 以下クエリで確認したところ0.00019秒以内に完了させる必要がありそうです.
select 1/sum(1/delay) from items where type not in (2, 7, 9, 17);
+------------------------+
| 1/sum(1/delay) |
+------------------------+
| 0.00019008828967422543 |
+------------------------+
1 row in set, 5955 warnings (0.05 sec)
1秒辺りのPoller Processのアイテム処理数は上記processのリストから計算し (例えば "poller #9 [got 243 values in 5.012972 sec" から算出して, 5.01/243 = 0.020), 負荷が高い時で 0.020/0.00019 = 105 のprocessが最低でも必要かなと想像しました.
Yasumi - 投稿数: 372
プロセスを100以上にあげると相応のリソースが必要ですし、最悪Zabbixダウンのリスクもあります。
その前にやれることはいくつかあります。
①監視間隔を広げる
現在のアイテムの監視間隔を広げれば、「1秒あたりの監視項目数」は減りますので
見直すことができるものは検討してみてください。
②Pollerを倍にする
まず20にしてみてください。
③キャッシュサイズを増強
VALUECACHESIZE=128M
上記を256MBにするなど。