5分間隔のデータ取得について

お世話になります。

5分間隔でネットワークトラフィックを取得しているのですが
データを出力してみたら、時々10分間隔にとんでいたりします。
(その時間サーバに負荷がかかっていたというわけでもないのですが…)
これはバグとして認識して良いのでしょうか?
(バージョンは1.8.2です)

以下、任意の時間を抜き出したものです。
ご教授お願いいたします。

select FROM_UNIXTIME(clock),value from history_uint where clock between UNIX_TIMESTAMP('2010-05-18 14:20:00')

and UNIX_TIMESTAMP('2010-05-18 14:50:00') and itemid=22460 order by clock;

+----------------------+----------+

| FROM_UNIXTIME(clock) | value |

+----------------------+----------+

| 2010-05-18 14:24:20 | 12984232 |

| 2010-05-18 14:29:20 | 12018680 |

| 2010-05-18 14:34:20 | 13583200 |

| 2010-05-18 14:44:20 | 14905824 |

| 2010-05-18 14:49:20 | 13101544 |

+----------------------+----------+

コメント表示オプション

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

こんにちは。

サーバの負荷が高くなかったということですが、Zabbixが利用しているMySQLサーバの負荷状況はどうだったでしょう?また、どのくらいの監視項目数を監視されているでしょうか?監視項目数などの情報は[レポート]->[Zabbixサーバのステータス]で確認できます。

MySQLをチューニングしないでZabbix用のDBとして利用するとパフォーマンスが出ずにポーリングが遅延することがあります。遅延しているポーリングの処理はWebインターフェースから[管理]->[キュー]で見ることができます。

ユーザー tak の写真

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

監視項目数は以下になります。
ホスト数 :4
アイテム数:147
トリガー :11
1秒あたりの監視項目数(zabbixサーバの要求パフォーマンス)
0.379
です。

MySQLのチューニングはやってみます。

取り急ぎ、ご返信まで。

ユーザー tak の写真

お世話になっております。

MySQLのチューニングの件ですが、ボトルネック(3秒以上かかるSQL)を先週から調べていましたが、特に見当たらないため今のところは必要なさそうです。

また、LoadAverageも常に低いため、負荷はほとんどないと考えてよさそうです。

ユーザー kodai の写真

アイテム数147程度ですと、それほど負荷も高くなさそうですね。

データが飛んでいる時間に、Zabbixサーバのログには何か関連しそうなエラーなどは出ていないでしょうか?

監視のタイムアウトなどでデータが取得できない場合はログにエラーメッセージが出力されるはずです。

ユーザー tak の写真

kodai様

お世話になっております。

>データが飛んでいる時間に、Zabbixサーバのログには何か関連しそうなエラーなどは出ていないでしょうか?
zabbixサーバのログを調べてみたのですが、データが飛んでいる時間に、それらしいエラーは見当たりませんでした。。
(下記エラーが一時間ごとに出ているだけでした
Executing housekeeper
Deleted 0 records from history and trends)

ユーザー kodai の写真

うーん、そうですか。。。

となると、Zabbixのバグかアイテムの設定に関する問題なのかもしれません。

こちらでも再現できるか試してみたいので、問題が発生しているアイテムの設定を教えていただけますか?アイテムの設定画面で表示される全ての設定項目を書いていただけると助かります。

ユーザー tak の写真

以下、問題のあるアイテムの詳細です。

ホスト :swext
説明 :InFa0/2
タイプ :SNMPv2エージェント
SNMP OID :.1.3.6.1.2.1.2.2.1.10.2
SNMPポート :161
キー :ifInOctets.2
データ型 :数値 (整数)
データの形式 :10進数
単位 :bps
乗数を使用 :乗数
乗数 :8
更新間隔(秒) :300
例外の更新間隔の作成 :間隔→50
期間→1-7,00:00-23:59
ヒストリの保存期間(日):90
トレンドの保存期間(日):730
ステータス :有効
保存時の計算 :差分/時間
値のマッピングの使用 :なし
アプリケーション :なし

以上です。
よろしくお願いいたします。

ユーザー kodai の写真

保存時の計算 :差分/時間

でデータの差分を時間で割っているので、結果は少数値が含まれる場合があります。

そのため、

データ型 :数値 (整数)

データ型は「数値(整数)」ではなく「数値(浮動小数)」を設定する必要があります。

おそらく、割った結果が整数の場合だけデータベースに保存され、少数値になった場合はエラーになってデータベースに保存されていないのではないかと思います。

ユーザー tak の写真

kodai様

データ型:数値(整数)から
データ型:数値(浮動小数)に変えたのですが
やはり以前と変わらずデータがたまに10分間隔に飛んでしまいます。。

SQLのログを取ってみたのですが
データ取得に失敗しているときはinsert文がありませんでした。
insertするべき箇所の前でupdateしていますが、下記のように違いがあります。

・成功
update items set lastclock=1280132960,prevvalue=lastvalue,prevorgvalue='3928056349.000000',lastvalue='16545689.093333' where itemid=22460

・失敗
update items set lastclock=1280135660,prevorgvalue='179379284.000000' where itemid=22460

何かお気づきの点はありますでしょうか?
よろしくお願いいたします。

ユーザー KTU の写真

takさんと同環境で作業しているktuと申します。
上記に補足いたします。

SQL情報から1.8.1のソースを見ると
\zabbix-1.8.1\src\libs\zbxdbcache
のdbcache.cの下記の条件分岐で、データベースに書き込まれている場合には真、書き込まれていない場合には偽になっているようです。
zbx_process == ZBX_PROCESS_SERVER
の値がわからないので内容は確認できませんが・・・。

if (zbx_process == ZBX_PROCESS_SERVER)
{
DCmass_update_item(history, history_num);
DCmass_add_history(history, history_num);
DCmass_function_update(history, history_num);
DCmass_update_triggers(history, history_num);
DCmass_update_trends(history, history_num);
}
else
{
DCmass_proxy_add_history(history, history_num);
DCmass_proxy_update_item(history, history_num);
}

ちなみに、本現象は、1.8.1,1.8.2,1.6.9でも発生いたします。

ご参考になれば幸いです。
よろしくお願いいたします。

ユーザー TNK の写真

zbx_processの値は、

 ZBX_PROCESS_SERVER
 ZBX_PROCESS_PROXY

のどちらかで、引用されていた部分は、
 zabbix_server

 zabbix_proxy
かの処理分岐だと思われます。

より具体的には、zbx_processの値は、関数init_database_cache()で初期化し設定されます。
具体的には、
 src/zabbix_proxy/proxy.c
 src/zabbix_server/server.c
から呼び出されているようです。

可能であれば、ログのレベルをデバッグレベルに設定できませんでしょうか?
そうすれば、詳細なログで確認できると思います。

ユーザー KTU の写真

TNKさん

レスありがとうございます。
早速設定しましたら結果が出ました。

#snmpコミュニティ名、IPは書き換えております。

--成功---
11859:20100802:170929 In get_value(key:ifInOctets.2)
11859:20100802:170929 In get_value_snmp(key:ifInOctets.2,oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170929 Standard processing
11859:20100802:170929 In snmp_normalize(oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170929 End of snmp_normalize():.1.3.6.1.2.1.2.2.1.10.2
11859:20100802:170929 In get_snmp(oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170929 SNMP [testcom@192.168.0.1:161:161]
11859:20100802:170929 Status send [0]
11859:20100802:170929 AV loop OID [.1.3.6.1.2.1.2.2.1.10.2] Type [0x41] Counter32: 817492738
11859:20100802:170929 OID [.1.3.6.1.2.1.2.2.1.10.2] Type [65] UI64[817492738]
11859:20100802:170929 OID [.1.3.6.1.2.1.2.2.1.10.2] Type [65] ULONG[817492738]
11859:20100802:170929 End get_value()
11859:20100802:170929 Query [begin;]
11859:20100802:170929 In process_new_value(ifInOctets.2)
11859:20100802:170929 In add_history(key:ifInOctets.2,value_type:3,type:1)
11859:20100802:170929 In add_history(itemid:22469,UINT64:817492738)
11859:20100802:170929 DBmultiply_value_float() 1776828,8 14214624
11859:20100802:170929 In add_history_uint()
11859:20100802:170929 Query [insert into history_uint (clock,itemid,value) values (1280736569,22469,14214624)]
11859:20100802:170929 In add_trend_uint()
11859:20100802:170929 Query [select num,value_min,value_avg,value_max from trends_uint where itemid=22469 and clock=1280736000]
11859:20100802:170929 Query [insert into trends_uint (clock,itemid,num,value_min,value_avg,value_max) values (1280736000,22469,1,14214624,14214624,14214624)]
11859:20100802:170929 End of add_history():SUCCEED
11859:20100802:170929 In update_item()
11859:20100802:170929 In calculate_item_nextcheck (22469,300,"",1280736569)
11859:20100802:170929 End calculate_item_nextcheck (result:1280736869)
11859:20100802:170929 DBmultiply_value_float() 1776828,8 14214624
11859:20100802:170929 Query [update items set nextcheck=1280736869,prevvalue=lastvalue,prevorgvalue='817492738',lastvalue='14214624',lastclock=1280736569 where itemid=22469]
11859:20100802:170929 End of update_item()
11859:20100802:170929 In update_functions(22469)
11859:20100802:170929 Query [select distinct function,parameter,itemid,lastvalue from functions where itemid=22469]
11859:20100802:170929 End update_functions()
11859:20100802:170929 In update_triggers [itemid:22469]
11859:20100802:170929 Query [select distinct t.triggerid,t.expression,t.description,t.url,t.comments,t.status,t.value,t.priority,t.type from triggers t,functions f,items i where i.status<>3 and i.itemid=f.itemid and t.status=0 and f.triggerid=t.triggerid and f.itemid=22469]
11859:20100802:170929 End update_triggers [22469]
11859:20100802:170929 Query [commit;]
11859:20100802:170929 End get_values()

--失敗---
11859:20100802:170429 In int_in_list(list:,value:10050)
11859:20100802:170429 End int_in_list(ret:FAIL)
11859:20100802:170429 In get_value(key:ifInOctets.2)
11859:20100802:170429 In get_value_snmp(key:ifInOctets.2,oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170429 Standard processing
11859:20100802:170429 In snmp_normalize(oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170429 End of snmp_normalize():.1.3.6.1.2.1.2.2.1.10.2
11859:20100802:170429 In get_snmp(oid:.1.3.6.1.2.1.2.2.1.10.2)
11859:20100802:170429 SNMP [testcom@192.168.0.1:161:161]
11859:20100802:170429 Status send [0]
11859:20100802:170429 AV loop OID [.1.3.6.1.2.1.2.2.1.10.2] Type [0x41] Counter32: 284444217
11859:20100802:170429 OID [.1.3.6.1.2.1.2.2.1.10.2] Type [65] UI64[284444217]
11859:20100802:170429 OID [.1.3.6.1.2.1.2.2.1.10.2] Type [65] ULONG[284444217]
11859:20100802:170429 End get_value()
11859:20100802:170429 Query [begin;]
11859:20100802:170429 In process_new_value(ifInOctets.2)
11859:20100802:170429 In add_history(key:ifInOctets.2,value_type:3,type:1)
11859:20100802:170429 In add_history(itemid:22469,UINT64:284444217)
11859:20100802:170429 End of add_history():FAIL
11859:20100802:170429 In update_item()
11859:20100802:170429 In calculate_item_nextcheck (22469,300,"",1280736269)
11859:20100802:170429 End calculate_item_nextcheck (result:1280736569)
11859:20100802:170429 Query [update items set nextcheck=1280736569,prevorgvalue='284444217',lastclock=1280736269 where itemid=22469]
11859:20100802:170429 End of update_item()
11859:20100802:170429 Query [commit;]
11859:20100802:170429 End get_values()

失敗時は
End of add_history():FAIL
となっていますね。

In add_historyの値(引数?)は特におかしいようには見えないのですが・・・。
#データ型は浮動小数です。

よろしくお願いいたします。

ユーザー TNK の写真

このログは、Zabbix 1.8.2ではなく1.6系のログではありませんか?

そうであるならば、src/libs/zbxserver/functions.cの340行目あたりの条件の何かに合致してしまっていると思われます。
例えば、

 ・DBに保存されている値よりも新しく取得した値の方が小さい場合
 ・DBに保存した時刻よりも現在時刻が前になってしまっている場合

などです。

考えられることとしては、

 ・SNMPを利用して取得する対象が再起動するなどしてカウンタがリセットされた
 ・時刻の同期が取れていないか同期の際の時間差(誤差)が大きくなっている

あたりでしょうか。
後者の場合、仮想化環境上にZabbixサーバを構築すると発生する可能性が高くなると思います。

デバッグログにすれば、もっと具体的に原因が特定できると思ったのですが、ご提供頂いてもこのくらいしか予想できませんでした。

ユーザー KTU の写真

TNKさん
ご指摘ありがとうございます。

>このログは、Zabbix 1.8.2ではなく1.6系のログではありませんか?
はい。1.6にしたら問題が解消するかと思い、バージョンを下げました。

> ・時刻の同期が取れていないか同期の際の時間差(誤差)が大きくなっている
こちらに関してですが、仮想環境でzabbixを構築しております。
試しに、1分間隔でsnmpで同データを取得したところ問題がなかったので時刻の同期を調査してみようと思います。

また、進展がございましたらご報告させていただきます。

ユーザー KTU の写真

時刻同期はされてましたが、結果は同様で、たまにデータが取得できてませんでした。

下記ntpq -pの結果です。
時刻はほぼ正確に見えるのですがやはり仮想サーバということが問題なのでしょうか。

remote refid st t when poll reach delay offset jitter
==============================================================================
*www1.test.co.j 192.168.0.100 4 u 378 512 377 0.456 -0.337 0.125
+www2.test.co.j 192.168.0.100 4 u 136 512 377 0.459 -0.116 0.114
+www3.test.co.j 192.168.0.100 4 u 250 512 377 0.504 0.199 98.137
LOCAL(0) .LOCL. 10 l 42 64 377 0.000 0.000 0.001

ユーザー TNK の写真

ntpqを実行したサーバは、大きな時刻の誤差は無いようですね。

時刻同期に問題が無いのであれば、後は他の条件である

・DBに保存されている値よりも新しく取得した値の方が小さい場合

に合致する場合かもしれません。

同じ<itemid>の一つ前の
<code>
In add_history(itemid:<itemid>,UINT64:<値>)
</code>
と<値>を比較してみてください。

もし、一つ前の値の方が大きければ、対象となる機器かSNMPエージェントに何らかの問題がある可能性が考えられると思います。

ユーザー tak の写真

TNK様

お世話になっております。

ログを調べたところ
以下のような結果が得られました↓
・前回
In add_history(itemid:22469,UINT64:3881562513)
・エラー時の値
In add_history(itemid:22469,UINT64:284444217)
(ちなみにこのUINT64と何でしょうか?)

おっしゃるとおり、
【DBに保存されている値よりも新しく取得した値の方が小さい場合】
に合致しました。

やはり、対象となる機器かSNMPエージェントに何らかの問題があるのですかね。。
もしどちらかに問題があるとすれば、どのように調査すれば良いのでしょうか?

漠然とした質問で申し訳ないですが
ご査収の程、お願いいたします。

ユーザー TNK の写真

(ちなみにこのUINT64と何でしょうか?)

恐らく、Unsigned Integer 64bit(64bitの符号なし整数)だと思います。

やはり、対象となる機器かSNMPエージェントに何らかの問題があるのですかね。。
もしどちらかに問題があるとすれば、どのように調査すれば良いのでしょうか?

対象となる機器でログなどは出力されていないのでしょうか?
もしくは、Trap投げるとかは設定されていますか?
もし設定されているのであれば、そこで何かTrapが挙がっていませんか?

そういった確認ができないのであれば、その機器のサポートにお問い合わせ下さい。
設定やファームウェア(またはOSなど)の更新で改善される場合もあるかもしれません。
とはいえ、ファームの更新で別の障害が発生する場合も考えられますので、試験環境で事前に試験を行うなど、十分にご確認の上でご対応下さい。

ユーザー fripper の写真

tak さん、TNK さん

・エラー発生前のログ In add_history(itemid:22469,UINT64:3881562513)
・エラー発生時のログ In add_history(itemid:22469,UINT64:284444217)

ここでの UINT64 は、TNK さんの仰るとおり、
unsigned int 64(bit)、64bit 整数のことです。

ただ、UINT64 扱いとなるのは、zabbix_server 側がデータを受け取って
以後、トリガー判定や DB 格納などのデータ処理を行う際の
取り扱いデータ型になります。

SNMP でのデータのやりとりでは、以下ログにあるように、
Counter32(unsigned int 32bit) での取り扱いとなります

AV loop OID [.1.3.6.1.2.1.2.2.1.10.2] Type [0x41] Counter32: 284444217

今回の事象を見ていると、SNMP 内部でのデータ処理が
unsigned int 32bit で行われているせいで、オーバーフローが
発生しただけではないでしょうか?
32bit だと、16進数で 0x00ffffffff 8桁まで扱えます

3881562513 -> 0x00E75BF191
284444217 -> 0x0010F44639
   実は... 0x0110F44639 なのでは?

また、ログに出力されていた SNMP OID を調べさせていただくと、
「IF-MIB::ifInOctets.2」となっていました。

OID [.1.3.6.1.2.1.2.2.1.10.2]

この OID の挙動は
「該当 Ethernet I/F において、起動後に受信したパケット数」と
なっています
累積数をカウントしているだけに、どうしてもオーバーフローは
避けられないのではないかと考えます。

tak さんが1分おきにテストした時は問題なかった、という点も
「その時はたまたまオーバーフローするタイミングと合わなかった」
のではないかと考えます。

ユーザー TNK の写真

fripperさん、フォローありがとうございます。

確かにログに「Counter32」とあることを確認しました。
Counter32なら、最大値が「4294967295」だったかと思うので、それを超えてしまったのだと思います。
最大値を超えてしまって、機器(SNMPエージェント)が恐らく0からカウントしなおしているのでしょう。

そうすると、Zabbixの監視間隔を短くして、計測できない(値が保存されない)期間を短くするような対応を行うことが良いのではないでしょうか。

ユーザー tak の写真

TNKさん、fripperさん

ご回答ありがとうございます!

この OID の挙動は
「該当 Ethernet I/F において、起動後に受信したパケット数」と
なっています
累積数をカウントしているだけに、どうしてもオーバーフローは
避けられないのではないかと考えます。

tak さんが1分おきにテストした時は問題なかった、という点も
「その時はたまたまオーバーフローするタイミングと合わなかった」
のではないかと考えます。

アイテムの設定を変える方向で
オーバーフローが発生しないようにするにはどういう設定にしたら良いでしょうか?

もしくは
データベースのカラムのデータ型設定を手動で変更するとしたらどのデータ型が最適でしょうか?

ユーザー TNK の写真

Zabbix側ではなく、機器(SNMPエージェント)側が32bitのようです。Zabbix側は64bitのようですので、より大きな値を扱えるでしょう。

機器(SNMPエージェント)側で32bitでしか扱えないのであれば、オーバーフローが発生しないようにすることは不可能だと思います。
私の手元にある機器でも同じOIDに関する値は、Counter32で32bitにしか対応しておらず変更もできないようなので、もしかしたら、オーバーフローは回避できないのではないでしょうか。

-- 追記 --
IF-MIBでifInOctetsは、Counter32と定義されているようです。
ftp://ftp.cisco.com/pub/mibs/v2/IF-MIB.my

ユーザー kodai の写真

ifInOctetsやifOutOctetsを64ビットで扱えるOIDがあったはずです。そちらを使えばカウンタ値がリセットされることも少なくなると思います。

具体的なOIDの値はすぐに分からないのですが、snmpwalkなどでOID一覧を出して、そこから探されてみてはいかがでしょうか。

ユーザー TNK の写真

ちょっと手元の環境で同じような値のエントリを探してみました。

もしかしたら、
 IF-MIB::ifHCInOctets.2(.1.3.6.1.2.1.31.1.1.1.6.2)
 IF-MIB::ifHCOutOctets.2(.1.3.6.1.2.1.31.1.1.1.10.2)
あたりかもしれません。

これらは、型がCounter64です。

ifHCInOctetsのDESCRIPTIONにも、

The total number of octets received on the interface,
including framing characters. This object is a 64-bit
version of ifInOctets.

とあるので、ifInOctetsの64bit版のようです。

ユーザー tak の写真

kodaiさん TNKさん

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

TNKさんに調べていただいた

もしかしたら、
 IF-MIB::ifHCInOctets.2(.1.3.6.1.2.1.31.1.1.1.6.2)
 IF-MIB::ifHCOutOctets.2(.1.3.6.1.2.1.31.1.1.1.10.2)
あたりかもしれません。

上記のOIDを設定したところ5分間隔のデータが抜けなく取得出来ました。
TNKさん、ありがとうございます!
やはりオーバーフローが原因だったようです。。

非常に助かりました。
皆様、ありがとうございます。