監視遅延の調査方法について

いつもお世話になっております。

表題の件について、確認させて下さい。
------------
■環境
ZabbixServer 1.8.3
ZabbixAgent 1.8.3
MySQL 5.0.77

Server性能
CPU Intel(R) Xeon(R) CPU E5502 @ 1.87GHz
MEM 12GB

ホスト数 (有効/無効/テンプレート) 303 201 / 53 / 49
アイテム数 (有効/無効/取得不可) 5494 3001 / 2372 / 121
トリガー数 (有効/無効)[障害/不明/正常] 2204 1890 / 314 [32 / 480 / 1378]
------------

■[監視データ] - [最新データ]
説明 最新チェック 最新の値 変更 ヒストリ
Free number of inodes on /drbd in % 2011 4月 04 22:35:35 100 % - グラフ

●上記アイテム登録内容
説明:Free number of inodes on $1 in %
タイプ:Zabbixエージェント
キー:vfs.fs.inode[/,pfree]
データ型:数値 (浮動小数)
単位:%
更新間隔(秒):86400

■キュー現状(上位遅延部分抜粋)
2011 4月 05 18:19:05 1y 1w Host名1 Free number of inodes on /drbd in %
2011 4月 05 18:19:06 1y 1w Host名2 Free number of inodes on /drbd in %
2011 9月 29 22:22:39 6m 2w 5d Host名3 Total disk space on /
2011 10月 25 18:19:00 5m 3w 2d Host名1 Free number of inodes on /drbd
2012 3月 01 14:29:16 1m 2w 2d Host名4 CPU nice time (avg1)
2012 3月 01 14:29:16 1m 2w 2d Host名4 MySQL number of slow queries
2012 3月 03 02:26:09 1m 2w Host名5 Total memory
2012 3月 28 09:22:33 2w 5d 7h Host名3 Free disk space on /
2012 3月 28 09:22:35 2w 5d 7h Host名3 Free disk space on / in %
2012 3月 28 09:22:37 2w 5d 7h Host名3 Used disk space on / in %
2012 3月 28 19:26:08 2w 4d 21h Host名6 Total memory
2012 3月 29 18:19:01 2w 3d 22h Host名2 Free number of inodes on /drbd
2012 3月 30 07:25:08 2w 3d 9h Host名6 Host information
2012 4月 04 12:25:09 1w 5d 4h Host名5 Host information
2012 4月 10 08:45:12 6d 7h 42m Host名5 Host uptime (in sec)
2012 4月 11 04:23:08 5d 12h 4m Host名6 Maximum number of processes
2012 4月 12 06:53:09 4d 9h 34m Host名5 Maximum number of processes
2012 4月 13 08:53:12 3d 7h 34m Host名5 Buffers memory
2012 4月 13 08:53:12 3d 7h 34m Host名5 Number of running processes memcached
2012 4月 13 22:43:01 2d 17h 44m Host名1 Processor load1
2012 4月 13 22:43:04 2d 17h 44m Host名1 CPU system time (avg1)
2012 4月 14 01:25:06 2d 15h 2m Host名5 Total swap space
2012 4月 14 14:15:11 2d 2h 12m Host名6 Host uptime (in sec)
2012 4月 15 06:41:37 1d 9h 45m Host名3 Number of running processes xinetd
2012 4月 15 08:56:44 1d 7h 30m Host名7 Number of processes
2012 4月 15 13:18:55 1d 3h 8m Host名1 Free disk space on /drbd in %

上記のように、特に重い監視ではないもので、遅延が発生しています。(グラフはたま~に点が付く程度です)
監視間隔の長い項目において、不具合がある等の情報はありますでしょうか。
agentlog , serverlogを確認しましたが、特に????となるような物は見当たりませんでした。
また、他サーバにて同じ項目を監視した場合、正常に毎回処理されております。
※ agentd.confのdiffでの見比べを行いましたが、特に差はありませんでした。
※ テンプレートを使用しておりますので、アイテム登録差はでないとの認識です。
→テンプレート適応後に個別に変更している可能性もありますが、
目視にて確認した所差はありませんでした。

http://www.zabbix.jp/node/430
http://www.zabbix.jp/node/624
症状としては、これらが近いのですが、agent監視です。
430側の場合、特に重い監視があるわけではないのですが、serverをデバッグモードで
起動し、発行したSQLを確認しない事には深くは調査できないでしょうか。

お気づきの点、確認点について、助言いただければと思います。

コメント表示オプション

お好みのコメント表示方法を選び「設定の保存」をクリックすると変更が反映されます。
ユーザー s.shibano の写真

お世話になります。

追加で気づいた点がありましたので、情報がありましたらご教示下さい。

エージェントログの過去ローテート分を遡って確認した所、
9050:20120120:125338.191 One child process died (PID:9056,exitcode/signal:255). Exiting ...
9050:20120120:125338.203 Can't find shared memory for collector. [No such file or directory]
15129:20120120:125338.349 Zabbix Agent started. Zabbix 1.8.3 (revision 13928).
15130:20120120:125338.350 zabbix_agentd collector started
15132:20120120:125338.351 zabbix_agentd listener started
15133:20120120:125338.351 zabbix_agentd listener started
15134:20120120:125338.352 zabbix_agentd listener started
15135:20120120:125338.352 zabbix_agentd active check started [**.**.**.**:10051]
15135:20120120:231158.283 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
15134:20120120:231158.283 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
15130:20120120:231158.283 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
15132:20120120:231158.283 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
15129:20120120:231158.283 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
15129:20120120:231158.284 Zabbix Agent stopped. Zabbix 1.8.3 (revision 13928).
15133:20120120:231158.284 Got signal [signal:15(SIGTERM),sender_pid:21932,sender_uid:0,reason:0]. Exiting ...
21946:20120120:231158.402 Zabbix Agent started. Zabbix 1.8.3 (revision 13928).
21947:20120120:231158.403 zabbix_agentd collector started
21949:20120120:231158.404 zabbix_agentd listener started
21950:20120120:231158.405 zabbix_agentd listener started
21951:20120120:231158.405 zabbix_agentd listener started
21952:20120120:231158.405 zabbix_agentd active check started [**.**.**.**:10051]
※IPのみアスタに変更させて頂きました。

9050:20120120:125338.191 One child process died (PID:9056,exitcode/signal:255). Exiting ...
9050:20120120:125338.203 Can't find shared memory for collector. [No such file or directory]
ログの中に上記子プロセスダウンのログがありまして、調べました所、
https://support.zabbix.com/browse/ZBX-1866
にいきつきました。
こちら、終了時にログに記載されるとの事ですが、タイミングとして終了時にログに記載されるだけで、
実は実行中落ちている可能性はありますでしょうか。
(psコマンドにて指定プロセス数が動いていても、実は応答してない等)

1.8.5以降を使えとの事ですが、現状すぐには対応できないので、この事象に該当する場合
定期再起動にて対応・・・?起動時する落ちるのか、ある程度は頑張ってるのか等についても
情報があれば幸いです。
※エージェントメモリを増やしてあげればある程度頑張れる!?

以上、よろしくお願い致します。

ユーザー TNK の写真

ご提示頂いた情報では、何が遅延している状態なのかがわかりませ
ん。
何をどうご覧になって「遅延している」と判断されたのかをお教え
ください。

また、アイテムとして「Free number of inodes on $1 in %」を挙
げられているのに、「キュー現状(上位遅延部分抜粋)」には、別の
アイテムの情報も挙げられています。
しかも、これだけの情報では、遅延していると判断できる情報がご
ざいません。

可能性として考えられることとして、例えば、アイテムのデータ取
得は、定期的にデータベースから値を取得すべきアイテムの情報を
取得して、Pollerと呼ばれる複数のプロセスで分担してZabbixエー
ジェントなどを呼び出して値を取得します。
各アイテムのデータ取得処理自体にも時間がかかりますし、同時に
取得しようとしたアイテム数が多い場合、Pollerの数が少ないと並
列で実行できる数も少ないので、全ての値の取得処理が終了するま
でに時間がかかってしまいます。
この場合、各アイテムのデータ取得間隔が、設定したものよりも長
くなってしまうことがあります。

このデータ取得間隔をご覧になって「遅延している」と判断された
のであれば、同じホストの同じアイテムに対するデータ取得の時刻
を連続で複数回分ご提示頂ければと思います。

また、同じテンプレートで設定している複数のホストに対するアイ
テムの取得時刻がずれているということであれば、ホストとアイテ
ムの組合せ毎にデータ取得時刻を管理していて、テンプレートのア
イテム単位で取得時刻を管理してはいないので、最初のデータ取得
タイミングがずれれば、データ取得間隔は同じでも、サーバ毎に取
得するタイミングはずれることになります。

最後に、アイテム取得間隔が指定した間隔よりも長くなってしまっ
ているのであれば、数秒であれば誤差の範囲ですし、分単位で間隔
が伸びてしまっているようであれば、キューにたまっていないかを
まずはご確認ください。
Webインターフェイスの「管理」->「キュー」でキューにたまって
いるかを確認することができます。

キューにたまってしまっていて、Zabbixサーバ自体の負荷に余裕が
あるのであれば、Pollerの数を増やすこともご検討下さい。

もしかしたら、途中でProxyを挟んでいたり、一時的にZabbixエー
ジェント側での処理が重くてタイムアウトが発生して値が取得でき
ない状況が発生していたのかもしれません。
この場合は、zabbix_server.confやzabbix_agend.confのTimeoutの
値を伸ばすことで改善できる場合があります。

基本的にZabbixでの不具合の修正対応は、バージョンアップでの対
応となります。
本当に、Zabbixエージェントのプロセスが落ちているのであれば、
プロセス監視を行えばよいと思いますし、プロセスが終了してしま
っていないのであれば、ZBX-1866のようなエラーはでないはずです。

ただ、バージョンアップされる際は、1.8.11ですと15文字以上のプ
ロセスのプロセス監視ができない問題がありますので、もうそろそ
ろリリースされる1.8.12でバージョンアップされることをご検討頂
いた方が良いと思います。

ユーザー s.shibano の写真

TNK様

ご返答ありがとうございます。

すみません、一回まとめさせて頂きます。

現在の監視状態
Ping監視については普段から全体的に30-40秒程度遅延が発生している(キューにて確認)
Agent監視については、一部のサーバ(4台程度)、一部のアイテムにて数時間~単位で遅延が発生している(キューにて確認)
→アイテムの設定にて差異が無い事を確認(テンプレート同士の確認です。)
→agentd.confを遅延が発生していないサーバとdiff確認を行い、Hostname、ListenIP以外に差異がない事を確認
⇒これらにより、監視設定による影響ではないと判断
その為、遅延原因の確認方法として、スレッドを作成させて頂きました。

その後、過去にローテートされたログを確認し、
子プロセスのdied、共有メモリ見失いのログを見つけ、同様の事象を調査し、
ZBX-1866に該当するのではないか?と判断し、追記投稿。
ZBX-1866にてagent終了時にログが記載されている、またpsコマンドではプロセスを確認できる為、
フリーズ状態(要求時応答不可)になっているのではないかと現在は考えており、
実行中の表示(ログ未記載、psコマンドでの表示確認)でも、実際に応答できるのかを確認する手段はありますでしょうか
また、zabbix_getでの一時的な確認では、該当していそうな物として、最初の投稿で上げました、
アイテムIDに紐付くプロセス割り当てにより、この方法では実際の登録アイテムとの動作が異なり、
確認できないとの認識ですが、合っていますでしょうか
※ キュー表示にて数時間~遅延しているアイテムに対して監視サーバより、zabbix_getした場合、
瞬時に応答があります。( zabbix_get -s ホスト名 -k キー )

> ご提示頂いた情報では、何が遅延している状態なのかがわかりません。
> 何をどうご覧になって「遅延している」と判断されたのかをお教えください。

説明不足で申し訳ありません。
最初の投稿にて、”■キュー現状(上位遅延部分抜粋)”に記載しております。
こちらは[管理]-[キュー]の内容となります。
ですので、左から[次のチェック][遅延時間][ホスト][説明]となります。
※一日以上の遅延の物を記載しております。
※また、キューの内容により、遅延と判断しておりましたが、
特定のサーバ、特定のアイテムにのみキューに遅延表記されております。
現在はZBX-1866に該当するのではないか?と考えております。

> このデータ取得間隔をご覧になって「遅延している」と判断された
> のであれば、同じホストの同じアイテムに対するデータ取得の時刻
> を連続で複数回分ご提示頂ければと思います。

すみません、先に例としてあげておりましたinodeについて、
記載しようと思ったのですが、遅延が1年以上となってまして、
ヒストリが残っておりませんでした。
コロコロ例のアイテムが変わってしまい申し訳ありませんが、
cpuのload avgのグラフをアップロード致します。

> また、同じテンプレートで設定している複数のホストに対するアイ
> テムの取得時刻がずれているということであれば、ホストとアイテ
> ムの組合せ毎にデータ取得時刻を管理していて、テンプレートのア
> イテム単位で取得時刻を管理してはいないので、最初のデータ取得
> タイミングがずれれば、データ取得間隔は同じでも、サーバ毎に取
> 得するタイミングはずれることになります。

こちらにつきましては、了解しております。
しかし、遅延が1日以上の物で絞った場合でも、
”■キュー現状(上位遅延部分抜粋)”となっております。

> キューにたまってしまっていて、Zabbixサーバ自体の負荷に余裕が
> あるのであれば、Pollerの数を増やすこともご検討下さい。

ご助言ありがとうございます。
しかし、全体的な遅延は主にPing監視ですが30-40秒程度で、
一部のAgent監視については、数時間~の遅延となっております。
その為、他に原因があるのではないかと考えております。

> もしかしたら、途中でProxyを挟んでいたり、一時的にZabbixエー
> ジェント側での処理が重くてタイムアウトが発生して値が取得でき
> ない状況が発生していたのかもしれません。
> この場合は、zabbix_server.confやzabbix_agend.confのTimeoutの
> 値を伸ばすことで改善できる場合があります。

説明不足ですみません。
同ネットワーク、同L2SW配下に監視サーバ、監視対象が存在します。
Pingでの確認(監視サーバ → 全ての監視対象サーバ)では
最大でも0.300msに届かない程度でした。

> 基本的にZabbixでの不具合の修正対応は、バージョンアップでの対
> 応となります。
> 本当に、Zabbixエージェントのプロセスが落ちているのであれば、
> プロセス監視を行えばよいと思いますし、プロセスが終了してしま
> っていないのであれば、ZBX-1866のようなエラーはでないはずです。

表現に問題がありました。すみません。
エージェント側を再起動(stop処理を実施する際に)追記投稿で記載しました
子プロセスのダウン、及び共有メモリ見失いのログが記載されます。
ですので、終了ではなく、フリーズ(要求時動作不可)の状態と推測しており、
監視できるような手段があればいいのですが。。。

上記で返答内容になっておりますでしょうか。

説明ベタでご迷惑をおかけしておりますが、
よろしくお願い致します。

ユーザー s.shibano の写真

TNK様

すみません、なんか色々深読みといいますか、全ての事象が当てはまっているような感覚で、
思い込みをしていたかもしれません。

キューがたまらない正常なサーバ、たまる異常なサーバでzabbix子プロセスをstraceにて、
追っかけてみましたところ、異常なサーバではgetpeername による接続元解決?で
時間がかかっているようです。

関係ないと考えておりました、下記、監視サーバのログが、
キューが遅れている異常な監視対象サーバのみ出力されている事に気づき、
下記のスレッド同様のタイムアウト値伸ばしを行い、変化を確認してみたいと思います。
http://www.zabbix.jp/node/831

※ 同アイテムは別テンプレートにて、正常な監視対象サーバでも使用しております。
※ 正常のサーバ、異常のサーバともに同ネットワーク同SW配下です。

■zabbix server log
Item [Host名1:net.tcp.service[ssh]] error: Get value from agent failed: ZBX_TCP_READ() failed [Interrupted system call]
Zabbix Host [lswnod11b]: first network error, wait for 15 seconds

■strace
[user@正常ホスト ~]$ cat 214* | grep getpeertail -f 2149.txt cat 214* | grep getpeer
2148 0.000025 getpeername(5, {sa_family=AF_INET, sin_port=htons(52531), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2148 0.000051 getpeername(5, {sa_family=AF_INET, sin_port=htons(52739), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2148 0.000052 getpeername(5, {sa_family=AF_INET, sin_port=htons(53582), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2148 0.000026 getpeername(5, {sa_family=AF_INET, sin_port=htons(53822), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2148 0.000049 getpeername(5, {sa_family=AF_INET, sin_port=htons(54081), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2148 0.000070 getpeername(5, {sa_family=AF_INET, sin_port=htons(54762), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000028 getpeername(5, {sa_family=AF_INET, sin_port=htons(39737), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000052 getpeername(5, {sa_family=AF_INET, sin_port=htons(39845), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000022 getpeername(5, {sa_family=AF_INET, sin_port=htons(40322), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000049 getpeername(5, {sa_family=AF_INET, sin_port=htons(40423), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000050 getpeername(5, {sa_family=AF_INET, sin_port=htons(40525), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000069 getpeername(5, {sa_family=AF_INET, sin_port=htons(40658), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000026 getpeername(5, {sa_family=AF_INET, sin_port=htons(40931), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000069 getpeername(5, {sa_family=AF_INET, sin_port=htons(40933), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000044 getpeername(5, {sa_family=AF_INET, sin_port=htons(41166), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000046 getpeername(5, {sa_family=AF_INET, sin_port=htons(41380), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000051 getpeername(5, {sa_family=AF_INET, sin_port=htons(41436), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000026 getpeername(5, {sa_family=AF_INET, sin_port=htons(42211), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000050 getpeername(5, {sa_family=AF_INET, sin_port=htons(42221), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000053 getpeername(5, {sa_family=AF_INET, sin_port=htons(42226), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0
2149 0.000051 getpeername(5, {sa_family=AF_INET, sin_port=htons(42616), sin_addr=inet_addr("監視サーバIP")}, [3467824627072368656]) = 0

[user@異常ホスト(最初の投稿でのHost名1にあたります。) ~]$ cat 2316* | grep getpeer
23165 1.200158 getpeername(5, {sa_family=AF_INET, sin_port=htons(44174), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 4.696028 getpeername(5, {sa_family=AF_INET, sin_port=htons(44324), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 32.666718 getpeername(5, {sa_family=AF_INET, sin_port=htons(45212), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 0.105426 getpeername(5, {sa_family=AF_INET, sin_port=htons(45286), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 1.108625 getpeername(5, {sa_family=AF_INET, sin_port=htons(45326), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 66.033158 getpeername(5, {sa_family=AF_INET, sin_port=htons(47506), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 25.348994 getpeername(5, {sa_family=AF_INET, sin_port=htons(48318), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 0.007033 getpeername(5, {sa_family=AF_INET, sin_port=htons(48377), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 1.006167 getpeername(5, {sa_family=AF_INET, sin_port=htons(48399), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 0.929407 getpeername(5, {sa_family=AF_INET, sin_port=htons(48888), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 7.127308 getpeername(5, {sa_family=AF_INET, sin_port=htons(49121), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 27.480218 getpeername(5, {sa_family=AF_INET, sin_port=htons(49961), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 0.864111 getpeername(5, {sa_family=AF_INET, sin_port=htons(49984), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 19.234717 getpeername(5, {sa_family=AF_INET, sin_port=htons(50465), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 0.247000 getpeername(5, {sa_family=AF_INET, sin_port=htons(50500), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23165 42.057173 getpeername(5, {sa_family=AF_INET, sin_port=htons(39826), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23166 9.706893 getpeername(5, {sa_family=AF_INET, sin_port=htons(41989), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23166 25.801653 getpeername(5, {sa_family=AF_INET, sin_port=htons(42721), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23166 1.668267 getpeername(5, {sa_family=AF_INET, sin_port=htons(42785), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 9.129950 getpeername(5, {sa_family=AF_INET, sin_port=htons(44768), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 6.210705 getpeername(5, {sa_family=AF_INET, sin_port=htons(45055), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 18.235894 getpeername(5, {sa_family=AF_INET, sin_port=htons(45473), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 0.105042 getpeername(5, {sa_family=AF_INET, sin_port=htons(45656), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 15.237038 getpeername(5, {sa_family=AF_INET, sin_port=htons(46081), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 18.783921 getpeername(5, {sa_family=AF_INET, sin_port=htons(46560), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 4.370103 getpeername(5, {sa_family=AF_INET, sin_port=htons(46710), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 14.662178 getpeername(5, {sa_family=AF_INET, sin_port=htons(47079), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 0.294968 getpeername(5, {sa_family=AF_INET, sin_port=htons(47105), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 3.769425 getpeername(5, {sa_family=AF_INET, sin_port=htons(47194), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 0.995977 getpeername(5, {sa_family=AF_INET, sin_port=htons(47248), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 15.077101 getpeername(5, {sa_family=AF_INET, sin_port=htons(47652), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0
23167 4.919277 getpeername(5, {sa_family=AF_INET, sin_port=htons(48233), sin_addr=inet_addr("監視サーバIP")}, [4050460305396858896]) = 0

ユーザー kodai の写真

上記のように、特に重い監視ではないもので、遅延が発生しています。(グラフはたま~に点が付く程度です)
監視間隔の長い項目において、不具合がある等の情報はありますでしょうか。

すでにご存知ではないかと思いますが、Zabbixのキューは「アイテムが次回監視されるべき時間」と「現在時刻」に差がある場合に表示されます。
Zabbixは前回のデータ取得時に、保存データとともに取得時間を記録するのですが、「次回監視されるべき時間」とは「前回に値が保存された時間+アイテムの監視間隔」です。
そのため、キューに溜まる原因としては監視処理が重くてデータの取得に時間がかかったり、データベースが重くて正しくデータが保存されていない、アイテムの取得がタイムアウトになっている場合など、いろいろと考えられます。

ログの中に上記子プロセスダウンのログがありまして、調べました所、
https://support.zabbix.com/browse/ZBX-1866
にいきつきました。
こちら、終了時にログに記載されるとの事ですが、タイミングとして終了時にログに記載されるだけで、
実は実行中落ちている可能性はありますでしょうか。
(psコマンドにて指定プロセス数が動いていても、実は応答してない等)

この問題に該当する可能性はありそうですが、これはエージェントの終了時に出ているログでしょうか?
だとすると、動作中のエージェントの監視遅延にはあまり関係がないように思います。
エージェントがフリーズ状態になるような問題はこれまで聞いたことがないですね。

Ping監視については普段から全体的に30-40秒程度遅延が発生している(キューにて確認)

Pingの監視はPingerプロセスにより行われています。デフォルトのPingerプロセスは1つだけなので、
監視対象が多いようでしたら、zabbix_server.confのStartPingerの値を増やしてみると効果があるかもしれません。

また、zabbix_getでの一時的な確認では、該当していそうな物として、最初の投稿で上げました、
アイテムIDに紐付くプロセス割り当てにより、この方法では実際の登録アイテムとの動作が異なり、
確認できないとの認識ですが、合っていますでしょうか

問題のアイテムがポーリング監視の場合(アクティブチェックでない場合)は、zabbix_getで試してみることにより
どのくらいの早さで値が帰ってくるかを確認できます。
もしzabbix_getでデータを取得して時間がかかるようなら、Zabbixサーバから監視した場合でも同程度の時間がかかることになります。

キューがたまらない正常なサーバ、たまる異常なサーバでzabbix子プロセスをstraceにて、
追っかけてみましたところ、異常なサーバではgetpeername による接続元解決?で
時間がかかっているようです。

ソースを見てみたのですが、getpeername()は主にtrapperプロセスで利用されているようです。
推測ですが、この問題が発生しているエージェントではアクティブチェックによるデータが多いということはないでしょうか?
もしかすると、trapperプロセスの処理が追いつかずにタイムアウトが発生したり、データ送信/保存の遅延が発生しているのかもしれません。
アクティブチェックでデータが送れない場合はエージェント側にもログが出るはずですので、そのあたりも確認されてみてはいかがでしょうか。

ユーザー s.shibano の写真

kodai様

返信が遅くなりました。すみません。

こちらの件につきまして、設定値変更による検証を行う前に問題が解決しました。
結果のみ記載致します。

■zabbix server log
Item [Host名1:net.tcp.service[ssh]] error: Get value from agent failed: ZBX_TCP_READ() failed [Interrupted system call]
Zabbix Host [lswnod11b]: first network error, wait for 15 seconds

こちらのエラー内容から、下記の記事同様、タイムアウト値を15秒へ設定変更を行い、
動作検証を行う予定でした。
http://www.zabbix.jp/node/831

しかし、こちらの検証を行う前に、[Host名1:net.tcp.service[ssh]] がたまたま?稼動し、エラーが上がったため、
アイテム登録内容を調査していくうちに、デフォルト設定ですと、IPが127.0.0.1へアクセスするとの記載を
Zabbixマニュアルにて確認しました。

監視サーバからのみ、SSH接続を許可している為、自分自身であってもssh接続ができない設定となっており、
その為、値が取得できずにいたようです。
自分自身に接続できない為、アイテムをproc.num[ssh]へ、トリガーを1未満となった時にアクションを実行するよう変更いたしました。

そうしましたところ、最初の投稿にて記載しました、”■キュー現状(上位遅延部分抜粋)”のように、
遅延が発生しておりました各アイテム監視が正常に値を取得できるようになり、全て解消されました。
※Pingについては設定変更できていないので、今だに30秒程度遅延していますが、Pingのみが残っている状況です。

下記と同じ事象となっているようでした。
http://www.zabbix.jp/node/430

お客様先のシステムの為、デバックモードや設定値変更が容易にできず、想定ばかりでご迷惑をおかけしました。

以上、ご対応頂き、ありがとうございました。