イベント発生からアクション実行が遅れる
いつもフォーラムを参考にさせていただいています。
今回調べても同様の例を見つけられなかったため、質問させていただきたく思います。
ZABBIX 1.8.5-1を導入して50台程度のサーバ・ネットワーク機器など監視しているのですが、時々イベント発生とアクション実行時刻に大きなズレが見られます。
先日、実際にアクション実行が必要なイベントが発生しているのに、Webコンソール上でアクションが「進捗中」ですら無い状態を目撃しました。
その際の対処として、試しにzabbixのサービスを再起動したところ、アクションが正常に実行されました。
こういった、アクション実行の遅延というものは起こるものなのでしょうか。
ご回答いただけると幸いです。宜しくお願いします。
TNK - 投稿数: 4742
該当するアイテムのチェック間隔が長い場合は、現象が発生してか
らZabbixが検知してアクションを起こすまでに時間がかかる場合が
あります。
あと、Webの画面は障害が発生したからといってリアルタイムでは
更新されず、デフォルトでは30秒間隔でしか更新されませんのでご
注意ください。
ご参考までに、該当するアイテムのチェック間隔と、それに対する
トリガーの設定をどのような設定にされているか、そして、どの程
度遅れるのかをお教えください。
Cuturn - 投稿数: 22
情報が少なくて申し訳ありません。
イベント発生からアクション実行まで、1時間ほど遅れる時があります。
また、アクションとしてメール送信を行っていますので、遅延の現象についてWeb画面とメールの両方で確認できています。
対象アイテムについて
アイテムはSNMPトラップ監視で、ZABBIXトラッパーとして登録したアイテムです。
トリガーについて
トリガーの条件式は以下の通りです。
({HOST.str(IF-MIB::linkDown)})=1
kodai - 投稿数: 1341
トリガーの条件式が間違っているように思います。条件式の書式は、
{hostname:itemkey.func()}=1
です。
アイテムやアクションがどのような設定になっているか分かりませんが、少なくともトリガーは正しく動作していないと思われます。
まずは適切なトリガーを設定するところを修正してみてください。
Cuturn - 投稿数: 22
すみません。
正しくは以下のものでした。
(({snmptraps:snmptraps.str(IF-MIB::linkDown)})=1)
トリガーが発生しているのは、監視データ-イベント メニューから確認済みです。
Cuturn - 投稿数: 22
失礼します。
調査として、以下のことを行いました。
・ZABBIXサーバ内で30分毎にcronでDateコマンドでログし続ける
・ZABBIXにて300秒周期でログを監視し、新規ログが有れば通知を行う
ログ監視アイテム
キー：log[/var/log/30mlog]
タイプ：Zabbixエージェント(アクティブ)
データ型：ログ
更新間隔：300秒
トリガー
(({Zabbix server:log[/var/log/30mlog].regexp(.*)})#0)
ZABBIXデータベースよりalertsテーブルを直接抜き出し確認した結果、9割方はイベント発生と同時に通知を行っていましたが部分的に下表のように遅延が発生しています。
-----------------------------------------
アクション時刻 イベント時刻 Date表記
18:33 18:33 18:30
20:07 20:07 20:00 ← 19:00,19:30がスキップされている
20:07 20:07 20:00 ← 同上
20:07 20:07 20:00 ← イベントから5分遅れの通知
20:32 20:32 20:30
21:04 21:02 21:00
21:36 21:32 21:30
22:20 22:02 22:00 ← 18分ほどアクション実行が遅れている
-----------------------------------------
何かわかることが有れば、ご教示いただけると助かります。
kodai - 投稿数: 1341
設定は正しく行われているように思うので、何かZabbixサーバの動作に悪影響を及ぼしそうなものはないでしょうか？
- Zabbixサーバのログには何もエラーなどが出力されていないでしょうか。
- データベースの負荷が高くなっているなど、パフォーマンスの状況も確認ください。(特にロードアベレージ、CPUのiowait値)
Cuturn - 投稿数: 22
CPUのiowait値を見たところ、
該当時間帯にて10%〜30%の高まりがみられました。
iowait 10%にてトリガーを設定し、同様にdateのログの遅延状況と突き合わせたところ
ほぼ確実にiowaitが高まった時間に遅延が発生していることがわかりました。
ロードアベレージについてはまだ調べられていませんので、取得するように致します。
0hr - 投稿数: 8
はじめまして。このスレッドが気になっています。といいますのもうちでも同じようにメール送信が最大で1時間以上遅れることがあるからです。
Dell PowerEdge T110 タワーサーバ メモリ4GB
# zabbix_server -V
Zabbix Server v1.8.8 (revision 21965) (28 September 2011)
Compilation time: Oct 8 2011 21:49:59
メール送信は sendmessage_smtp_php.sh を利用しています。
ホスト数は18
要求パフォーマンスは 15.24/sec
程度です。DBも同マシンで稼働しています。
アクション遅延の発生に気づいたのは「計画停電」が実施されたときでした。計画停電のとき以外でも、マシンの再起動で「ICMP ping」障害通知が40分以上遅れるときがあります。
ZABBIXサーバには自由にアクセスできないためログの確認などはできていません。
サーバの負荷が原因だとしても、監視対象マシンの再起動程度で数十分アクションが遅れてしまっては「監視」にならないので、もちろん十分調査する予定ですが、なにか助言をいただけたら、という思いでポストした次第です。
よろしくお願いいたします。
kodai - 投稿数: 1341
複数の環境で同じ問題が起こっているということは、どこかに原因がありそうですね。双方の環境とも、データベースの負荷はそれほど高くないように見えます。
確認をお願いしたいのですが、
- アクションの設定を教えてください
- Zabbixサーバのログには関係しそうなエラーやデータベースがらみのエラーは出ていないでしょうか
- 遅延が発生していた通知が、実行される際の条件があれば教えてください(同じトリガーのステータスが変わったときなど)
こちらでうまく再現できれば解決の糸口がつかめると思います。
0hr - 投稿数: 8
お返事ありがとうございました。
本サーバのものではないですが、以下のようなものと同等です。
イベントソース トリガー
アクションのコンディション
計算のタイプ (A) and (B) and (C)
コンディション
(A) トリガーの値 = "障害"
(B) トリガーの名前 含まれない "ログ"
(C) アプリケーション 含まれない "WEB"
アクションのオペレーション
詳細 アクション
メッセージの送信先 ユーザ "Admin"
オペレーションのタイプ メッセージの送信
メッセージの送信先 シングルユーザ Admin
次のメディアのみ使用 メール送信スクリプト（PHP)
ユーザのメディア メール送信スクリプト（PHP) mail@address 1-7,00:00-24:00; NIWAHD
デフォルトのメッセージ checked
すみません、ログは後日チェックする予定です。
手元の環境での話ですが、あるマシンをシャットダウンすると、
icmpping で不通障害→イベント→アクションで通知がきます。このときZABBIXサーバでキューが滞留して負荷の高まりが確認できます。ただし、手元の環境での通知遅延はみられません。
本サーバは２機を何度か再起動したケースで、最初の再起動時に icmpping 不通通知が遅延なく送信されて、そのリカバリ通知が７分程度遅れて送信されていました。再起動が繰り返されて40分程度の遅延が確認できています。
以上、不十分な情報ですが、よろしくお願いします。
0hr - 投稿数: 8
お世話になります。
メール送信スクリプト（PHP)が原因かな、という結論に達しようとしています。
イベント→アクションでスクリプトが実行されますが、実行に数秒、ときには十数秒時間がかかっているのが確認されました。宛先が2件あるので１アクションに2回のスクリプト実行になります。スクリプトは順次実行されているようですので、徐々に遅れが大きくなっていくのでしょう（たぶん）。
スクリプトではなく、Emailのほうで対応しようかと思います。
kodai - 投稿数: 1341
情報ありがとうございます。
phpのスクリプトはこのサイトからダウンロードされたものを利用されているのでしょうか？もしそうでしたら、どのスクリプトを利用されているのか教えていただけると助かります。
0hr - 投稿数: 8
お世話になります。
sendmessage_smtp_php.tar.gz こちらを利用しています。
よろしくお願いします。
tsuzuki - 投稿数: 78
0hrさん
Zabbix-JPの鈴木です。
もし、「進捗中」の表示がされていて遅延が発生している場合は、メール送信スクリプトが遅延になります。
sendmessage_smtp_php.sh を単体でコマンドラインから以下のように実行してメール送信した時に、時間がかかるような状態になっていないか確認してください。
時間がかかるような状態になっている場合には、メールサーバの遅延が原因と思われますので、メールサーバの遅延を無くすことがベストかと思います。
$ ./sendmessage_smtp_php.sh mailaddress@example.com subject text_body
(mailaddress@example.com は有効なメールアドレスに置き換えてみてください)
ただ、それでも順次メール送信し終わるまで時間が掛かることを避けたい場合には、以下のスクリプトをsendmessage_smtp_php.shと同じディレクトリに置くことで対応できます。(sendmessage_smtp_php_nowait.sh という名前にしてください)
####################################################################
#!/bin/bash
nohup $(dirname $0)/sendmessage_smtp_php.sh "$@" > /dev/null 2>&1 &
####################################################################
設定後に、以下コマンドでメールが送れることを確認してメディアに登録するスクリプトの名前を sendmessage_smtp_php_nowait.sh に換えてください。
$ ./sendmessage_smtp_php_nowait.sh mailaddress@example.com subject text_body
(mailaddress@example.com は有効なメールアドレスに置き換えてみてください)
↑のスクリプトが何をやっているかというと、メール送信し終わるまで待たずに処理が返ってくるようになっています。
そのため、起動だけ順次処理して、並列でメール送信処理が行われます。
【注意点】
並列で処理するためにメールサーバにはより多くの負荷がかかり、ZabbixServer上においても複数のプロセスが動作することになります。
その点はご注意ください。
補足ですが、Zabbix 1.8系では1.8.7まではスクリプト実行が完了するまで永遠に待ちつづける動作になっているため、特に遅延が大きくなる傾向があります。
そして1.8.8からは40秒経ってもスクリプト実行が完了しなかった場合は次の処理に移るようになりました。そのため遅延発生しても最悪でも40秒で次の処理に移るようになっています。
なお、0hrさんは1.8.8を使用されているとのことなので、これはあまり関係ないとは思います。
tsuzuki - 投稿数: 78
Zabbix-JPの鈴木です。
長くて申し訳ないですが、障害通知が遅延する原因箇所は大きく分けて4箇所存在します。
ちょっとその解説をさせてください。
まず、ZabbixServerでは複数の役割をもったプロセスが協調動作してその結果さまざまな処理を実現しています。
今回の問題である障害通知処理については、以下の順序で複数のプロセスが処理を実行しています。
（なお、Poller、Trapper、DBSyncer、Escalator、Alerter というのは役割別の各プロセスの名前です。）
======================================================================
Poller または Trapper（監視実行、またはアクティブ監視データ受信）
・Zabbix Agent から受け取ったヒストリデータをメモリ上へ保存（この時点でヒストリとイベントに記録される「時刻」が決まる）
↓
DBSyncer（メモリからDBへデータ同期）（通常はPoller、Trapperの処理から10秒以内くらい）
・「events」テーブルにイベントを登録（この瞬間にWebのイベント画面からイベントを確認可能）
・アクション実行する場合には「escalations」テーブルへアクション実行情報を登録
↓
Escalator（アクション実行前処理）（通常はDBSyncerの処理から10秒以内くらい）
・「escalations」テーブルの内容を元に「alerts」テーブルへ情報を登録（この瞬間にイベント画面に「進捗中」表示がされる）
↓
Alerter（アクション実行）（zabbix_server.conf の SenderFrequency 秒間隔）
・「alerts」テーブルのアクション実行予定情報を元にアクションを実行（完了した瞬間にイベント画面に「OK」とかの表示がされる）
======================================================================
上記の通りの動作になっているため、以下のようにイベント画面の表示によってどこで遅延が発生しているかがわかります。
■例えばアクション実行されるべきイベントに全て「進捗中」が表示されつつ遅延が発生している場合
Alerterプロセスで遅延が発生していると考えられ、最も可能性として大きいのは実行しようとしている外部プロセスの遅延やメール送信の遅延です。
遅延している原因であるプロセスが高速に処理されるようにメールサーバを強化したり、もしくはプロセスを起動だけして切り離すようにすると効果があります。（sendmessage_smtp_php_nowait.sh はプロセスを切り離しているパターンです）
■例えばアクション実行されるべきイベントに「進捗中」が表示されず、少しずつ「進捗中」が増えてくるような遅延が発生している場合
Escalatorで遅延が発生していると考えられます。
このプロセスはDBの処理がメインなので、zabbix_server.confでLogSlowQueries=3000とか設定して、遅いクエリを抽出して何が原因か判定する必要があります。
■例えばそもそもイベント画面にイベント表示されること自体が遅延している場合
「Poller または Trapper」もしくは「DBSyncer」の遅延のどちらかが疑われます。
(1)イベント画面に表示された直後にも関わらず、イベント画面に表示されるイベントの「時間」が大きく過去の時間にずれている場合
「DBSyncer」の遅延が疑われます。
DB負荷に余裕がある場合には、zabbix_server.conf の StartDBSyncers の数を増やすと並列で処理される数が増えるため効果があります。
DB負荷に余裕がない場合には、DBが遅いのが原因と思われます。設定やHW増強でDBを高速化する必要があります。
(2)イベント画面に表示された直後でも、イベント画面に表示されるイベントの「時間」が大体正しい時刻の場合
「Poller または Trapper」の遅延が疑われます。
zabbix_server.conf の StartTrappers や StartPollers の数を増やすと並列で処理される数が増えるため効果があります。
よろしくお願いします。
Cuturn - 投稿数: 22
ご無沙汰しておりました。
お世話になっております。
私の方の環境でも様々確認しました。
・CPUのロードアベレージ
⇒負荷の高いときで1、平均0.12と特に問題ありませんでした
・送信アクション
⇒メール送信はsendmessage_smtp_php.shを使用しています
・エラーメッセージ
⇒遅延とあわせて発生するエラーはありませんでしたが、時々以下のようなエラーは出ています。
[Z3005] Query failed: [1062] Duplicate entry '22451-1322938800' for key 'PRIMARY' [insert into trends_uint (itemid,clock,num,value_min,value_avg,value_max) values (22451,1322938800,1,1,1,1); ]
遅延発生のタイミングで必ずiowaitが高まっていること、
鈴木さんの書き込みのEscalatorプロセスとDBSyncerのくだりからDBの負荷が高いのではないかと推測しています。
お恥ずかしい事ながらinnodb_buffer_pool_sizeが64MBしか割り当っていなかったので、mysqlのチューニングをきちんと実施して経過を見る予定です。
以上です。
Cuturn - 投稿数: 22
お世話になっております。
MySQLの割当を800MB程度に増やすなど実施いたしましたが、特に効果は見られず、遅延は依然として見られる状況です。
昨日観察した結果含め、改めて現象について報告します。
昨日発生した遅延について時系列順に現象を追うと以下のとおりとなります。
長くなってしまい申し訳ありませんがご了承ください。
********遅延期間?********
1 19:30 普通にイベント処理され、メール通知が行われる
2 19:34 イベントにてメールアクションが実施されていないものがある
escalationsテーブルには対象のイベントIDのデータが存在する
何故かZABBIXサーバのみsystem.cpu.utilパラメータが一定になり始める
3 20:17 キューが滞りはじめ、全てのホストの全てのアイテムの監視が進まなくなる
4 20:33 依然としてキュー滞留
5 20:42 2のアクションが実行される ただしキューはまだ処理されない
6 20:49 キューが一気に処理され、全てのホストの全てのデータが時間含め正常にDBに書かれる
ただしZABBIXサーバ自体のログ監視ついては時間が現在時刻
この時点からZABBIXサーバのsystem.cpu.utilパラメータがばらつき始める
8 20:50 新しいアイテムによるイベントも全てメール通知など完了する
********遅延期間?********
1 21:18 何故かZABBIXサーバのみsystem.cpu.utilパラメータが一定になり始める
2 21:32 普通にイベント処理され、メール通知が行われる
3 21:34 1つのイベントが登録されるが、アクションが実施されていない
escalationsテーブルには対象のイベントIDのデータが存在する
4 21:59 キューに溜まり始める
5 22:50 解消しているらしい(後日確認)
この時点からZABBIXサーバのsystem.cpu.utilパラメータがばらつき始める
どうにも複合的に遅延が発生していて判別に困ります。
「アクションが実行されない」時点ではEscalator処理が遅れており、
「キューが溜まり始める」時点ではDBSyncer処理が遅れている、ということになります。
イベント時刻は適切に保存されているので、PollerとTrapperには問題が無いように思えます。
微妙にZABBIXサーバだけログ監視とsystem.cpu.utilの動きが違うのが気になりますが…。
何かご助言いただければ幸いです。
以上です。宜しくお願いいたします。
TNK - 投稿数: 4742
キューの滞留が発生しているとのことですが、tsuzukiさんが書か
れていた、
に関して、何か確認されましたでしょうか？
サーバの負荷が低く、データベースの応答にも問題がないのであれ
ば、監視対象の数とそれぞれの処理時間に対して、PollerやTrapper
の数が不足している可能性が考えられます。
StartPollersやStartTrappersの値を大きくすることで、並行して
処理できる数が増加し、キューの滞留が改善できるかもしれません
ので、ご確認ください。
Cuturn - 投稿数: 22
TNKさん
上記について、StartTrappersとStartPollersの値を初期値5から10に変更いたしましたが、特に改善は見られませんでした。
ZABBIXサーバサービスを再起動すると適切にキューが流れ始めるので、今のところは30分に一度くらいサービス再起動を行うしかないかもしれません。
以上です。
0hr - 投稿数: 8
0hr です。
鈴木さま、詳細な解説本当にありがとうございました。
「進捗中」がでています。それと、なんということでしょう、コマンドラインからsendmessage_smtp_php.sh を単体で実行すると以下のように時間がかかっていました。
sendmessage_smtp_php]# time ./sendmessage_smtp_php.sh my@address.jp smtp body
success
real 0m17.173s
user 0m0.028s
sys 0m0.014s
こちらは、SMTPサーバをIPアドレス指定に変更して対応しました。
それから、お教えくださったように sendmessage_smtp_php_nowait.sh を作成してメディアに登録して試しています。
こちら貴重な情報、ありがとうございました。
しばらく様子をみてみます。