zabbix-serverが強制終了してしまう現象について
別投稿からの分離です。
最近本格的にサービスサーバの監視を開始したのですが、時々zabbix-serverが
強制終了する事態が発生し始めました。終了した時のzabbix-serverのログには
14923:20100224:205853.436 ERROR: nested transaction detected. Please report it to Zabbix Team.
zabbix_server: db.c:380: zbx_db_begin: Assertion `0' failed.
もしくは
18370:20100224:071746.100 One child process died (PID:18456). Exiting ...
18370:20100224:071748.140 Syncing history data...
といったログが出力されていました。
このログの前には何も表示されておらず、いきなり上記2パターンのログが出力された後に
zabbix-serverが終了しようとしていた模様です。しかも正常に終了できず、全てのプロセスがdefunctしていました。
監視サーバの環境は以下の通りです。
OS:Gentoo Linux
Memory:1GB
監視台数:120台
zabbix-1.8.1
apache 2.2.14
postgresql-8.4.1
php-5.2.6
Zabbixサーバの要求パフォーマンス:39
別データセンタのサーバを監視している方のzabbix-serverの方は一度も強制終了していません。
そちらの監視台数は70台程度でZabbixサーバの要求パフォーマンスは53となっています。
zabbix_server.confで各プロセスの数を増やしたり、キャッシュサイズ等を増やしても
特に変化は見られませんでした。
応急処置として、defunctしたらzabbix_serverのpsをkillって再起動するスクリプトを
cronに仕込んで対処していますが、根本的な原因が分からないのでアドバイス等、頂けたら幸いです。
よろしくお願い致します。
KAZ - 投稿数: 1085
MINTIAさん
Gentoo Linuxは私が弄ったことのないOSで、その環境を手元に作るには少々時間がかかりそうです。(本業が忙しいとちょっと厳しいです。)
少々ログ情報を提供願えると、それをもとに調査ができると思いますので、申し訳ないですが御協力頂けますか？
上記はかなりバグっぽいです。
DBアクセスでトランザクションをスタートを２重にすると発生します。なので、直前に何の処理をしているかが分かると調査ができます。できればログレベルを４にして頂き、ダウン時の当たりのログを頂けると助かります。
「Syncing history data...」キャッシュ機能で出力されるログなのですが、問題はその前の「One child process died」でこれはどこで問題が起きているかこの情報では不明です。
これもログレベルを4にして頂き、ダウン時の当たりのログを頂けると助かります。
あと、1.8系のソースは読み始めたばっかりで解析に時間がかかるかもしれません。御了承下さい。m(__)m
kodai - 投稿数: 1341
こんにちは。
今までに見たことがないエラーですね。1.8からはデータベースへの接続が以下のように変わっています。(正確にはソースを見れていないのですが)
- データベース接続用のプロセスが存在する (1.6までは各プロセスがDBに接続していた)
- DB書き込みの際のキャッシュモジュールが追加された
このあたりの処理変更にともなってバグがあるのかもしれません。
負荷が原因かもしれないと書かれていましたが、Zabbixサーバにはかなり負荷がかかっているのでしょうか？
KAZ - 投稿数: 1085
kodaiさん
MINTIAさん
トランザクションがクローズされないと、該当箇所への書き込みはWAITしますので、溜まってくるとかなりの負荷になるかと。
MINTIA - 投稿数: 40
最初に強制終了し始めた時にログレベルを4にしたのですが、ログサイズが
かなりの大きさになってしまったのと、何故かログレベルを4にした時には
強制終了した時も上記のログが出ていない上に、ログが途中で切れていました。
なので結局ログレベルを3に戻してしまいました・・・
ログレベル3の直近のログですと以下の通りです。
21337:20100301:152805.055 ERROR: nested transaction detected. Please report it to Zabbix Team.
zabbix_server: db.c:380: zbx_db_begin: Assertion `0' failed.
8216:20100301:152807.551 Starting zabbix_server. Zabbix 1.8.1 (revision 9702).
8216:20100301:152807.551 **** Enabled features ****
8216:20100301:152807.551 SNMP monitoring: YES
8216:20100301:152807.551 IPMI monitoring: NO
8216:20100301:152807.551 WEB monitoring: YES
8216:20100301:152807.551 Jabber notifications: NO
8216:20100301:152807.551 ODBC: NO
8216:20100301:152807.551 SSH2 support: NO
8216:20100301:152807.551 IPv6 support: YES
8216:20100301:152807.551 **************************
8312:20100301:152843.110 server #1 started [DB Cache]
8319:20100301:152843.114 server #8 started [Trapper]
8322:20100301:152843.114 server #11 started [ICMP pinger]
8318:20100301:152843.114 server #7 started [Trapper]
8324:20100301:152843.114 server #13 started [Alerter]
8331:20100301:152843.118 server #20 started [Escalator]
8216:20100301:152843.122 server #0 started [Watchdog]
8330:20100301:152843.122 server #19 started [DB Syncer]
8320:20100301:152843.122 server #9 started [Trapper]
8321:20100301:152843.126 server #10 started [ICMP pinger]
8323:20100301:152843.126 server #12 started [ICMP pinger]
8325:20100301:152843.126 server #14 started [Housekeeper]
8326:20100301:152843.126 server #15 started [Timer]
8329:20100301:152843.130 server #18 started [Node watcher. Node ID:0]
8328:20100301:152845.230 server #17 started [Poller for unreachable hosts. SNMP:YES]
8317:20100301:152845.230 server #6 started [Poller. SNMP:YES]
8327:20100301:152845.234 server #16 started [Poller for unreachable hosts. SNMP:YES]
8316:20100301:152845.234 server #5 started [Poller. SNMP:YES]
8313:20100301:152845.242 server #2 started [Poller. SNMP:YES]
8315:20100301:152845.242 server #4 started [Poller. SNMP:YES]
8314:20100301:152845.258 server #3 started [Poller. SNMP:YES]
8216:20100301:160903.986 One child process died (PID:8320). Exiting ...
8216:20100301:160906.098 Syncing history data...
8216:20100301:160916.714 Syncing history data...0.771361%
8216:20100301:160926.874 Syncing history data...1.688104%
8216:20100301:160936.842 Syncing history data...2.475206%
8216:20100301:160946.045 Syncing history data...3.206749%
8216:20100301:160956.041 Syncing history data...3.947551%
8216:20100301:161005.637 Syncing history data...
8216:20100301:161005.665 ERROR: nested transaction detected. Please report it to Zabbix Team.
zabbix_server: db.c:380: zbx_db_begin: Assertion `0' failed.
15時28分にcronが回ってzabbix-serverが再起動されました。
そしてその後16時までは何もログが出ておらず、いきなりOne child process died
している感じですね。
そしてSyncing history data...のところでnested transaction detectedが出ています。
もう一度ログレベルを4にしてみます。
KAZ - 投稿数: 1085
MINTIAさん
メモリ破壊が起きているかも…
その時のログはありますか？
私のメールアドレスを送りますので、そこに圧縮したログを送って頂けると助かります。
「One child process died」は「Trapper」のプロセスが死んだと言ってますね…
推測ですがレベル４で出力したログが切れる前に走ったところにメモリ破壊しているところがあるのではないかと…
一応、Syncing history dataも調査してみます。
MINTIA - 投稿数: 40
サービスサーバの情報が含まれているので、無加工ログの提出は
上からストップがかかってしまいました・・・。ですので、現在ログを加工中です。
引き続き怪しいログを発見し次第ご報告致します。
KAZ - 投稿数: 1085
MINTIAさん
※：現在、「最後のERROR」について修正内容検討中です。 3/8(月) 17:30
※：間違いがありました。3/5(金) 17:00
ログの解析結果の中間報告です。
<code>
…中略…
8320:20100301:152843.122 server #9 started [Trapper]
…中略…
8216:20100301:160903.986 One child process died (PID:8320). Exiting ...
8216:20100301:160906.098 Syncing history data...
8216:20100301:160916.714 Syncing history data...0.771361%
8216:20100301:160926.874 Syncing history data...1.688104%
8216:20100301:160936.842 Syncing history data...2.475206%
8216:20100301:160946.045 Syncing history data...3.206749%
8216:20100301:160956.041 Syncing history data...3.947551%
8216:20100301:161005.637 Syncing history data...
8216:20100301:161005.665 ERROR: nested transaction detected. Please report it to Zabbix Team.
zabbix_server: db.c:380: zbx_db_begin: Assertion `0' failed.
</code>
まず、最後のERRORですがこれは根本原因ではないようです。
どちらかと言うと、２次災害です。
main_dbsyncer_loop関数はぐるぐるループしDCsync_history関数が定期的に呼ばれています(DCsync_history関数が「Syncing history data...」を出力する)。[d]コネクションはループの外で１回接続したものを使いまわします。[/d] 3/5(金) 17:00
上記ログはPID:8320のTrapperが異常終了して、終了シーケンスに入っています。この時、終了時は別ルートでDCsync_history関数が呼ばれます。[d]コネクションはmain_dbsyncer_loop関数を使いまわします。[/d] 3/5(金) 17:00
と言う訳で、キャッシュ処理を使うと終了時にトランザクション・スタートが２重に発生する可能性があります。(まぁ、バグですよね…)
[d]終了時のコネクションを別にすれば最後のERRORは解決するかと…[/d] 3/5(金) 17:00
違いました、コネクションは別になってます。トランザクションを管理している変数の問題でした。 A(^^;
※：根本原因はTrapperの異常終了ですが…A(^^;
MINTIA - 投稿数: 40
KAZさん
なるほど・・・つまりTrapperが異常終了さえしなければ、このバグも引き起こされないと。
Trapperの負担を下げるために、監視項目を減らす＆間隔を全体的に長めにしたところ
異常終了する回数はぐっと減りました。以前は数時間おきに異常終了していましたが、現在は
数日おきになっています。
ただ、プロセスも立っててログにも何も異常は出ていないのに管理画面に入ってみると
Zabbix-serverの起動が「いいえ」になっていて、実際にデータも受け取ってないし
死活監視などもしていない、という状況もありました。
サーバスペック的に一杯一杯になってる感がしますね・・・
kodai - 投稿数: 1341
ログの受信量が多い場合は、Trapperのプロセス数が不足してパフォーマンスが出ない場合がありますので、zabbix_server.confの以下の行でTrapperプロセスの数を増やされてみてはどうでしょう。
StartTrappers=5
デフォルトは5に設定されています。あまり多くしすぎても負荷がかかったりするので、同時にログを送信する監視対象の数より少し多目を設定するのが良いと思います。
MINTIA - 投稿数: 40
1ヶ月近く立ちましたが監視アイテムを減らす事で
強制終了は全く発生しなくなりました。
トラッパーが原因という事を教えて頂いたお陰で、対処の
見極めがし易くなりました。
具体的な対策としてはTrapperプロセス数を増やした上で
ログ監視のアイテム設定で、DBに取り込むログを絞りました。
1.8.2にはまだアップデートしていませんが、強くアップデートが
推奨されているので、近いうちにアップデートしてみようと思います。
有難うございました。