events.clockの値が、events.eventidと前後してました。(「障害」より先に「回復」している)

Zabbixイベントのタイムスタンプが不思議なことになっていました。
これは仕様通りなのでしょうか?それともバグでしょうか?

事象:
 Zabbixがイベントを検出したのですが、そもそも当該のトリガに抵触するような状態になっておらず、
 また、Zabbixコンソール⇒最新データ⇒イベント 上を見ると通常の「障害」→「回復」ではなく、「回復」⇒「障害」の順序で表示されている。

Zabbix Version :Zabbix3.0.7
mysql Version : MySQL 5.6.34
対象アイテム: agent.ping
更新間隔: 300秒
対象トリガ: {ip-10-0-x-x:agent.ping.nodata(5m)}=1

イベント検出時刻:
補足: 
・ほぼ同時刻のZabbix_Server.Logに「slow query」が出力(このアイテム、トリガのクエリではないですが)
・最新データ上の取得値はずっと「1」かつ5分以内にデータを取得できている(トリガに抵触しないはず)

〇mysqlテーブル上の内容

イベントテーブル (idと、clockの順序が逆転している)
eventid | clock | value
186323 |   2017-07-19 14:27:00 | 1
186324 |  2017-07-19 14:26:39 | 0

ヒストリ(ずっと5分間隔で取得できており、トリガに抵触しないはず)
+------------+---------------------+-------+
| name | history_clock | value |
+------------+---------------------+-------+
| Agent ping | 2017-07-19 14:16:39 | 1 |
| Agent ping | 2017-07-19 14:21:39 | 1 |
| Agent ping | 2017-07-19 14:26:39 | 1 |
| Agent ping | 2017-07-19 14:31:39 | 1 |
+------------+---------------------+-------+

〇推測
以下のように動作したと推測していますが、正しいでしょうか?(すいません、ソースは読めてないです。)

1) 14:21:39 に監視データ取得⇒historyに書き込み
2) slow query発生(mysqlへのIO遅延)
3) 14:26:30 に監視データ取得⇒IO遅延のため即時にhistoryに書き込みできず!!!
4) 14::27:00 にトリガチェック処理が動作 ⇒history上、3)のレコードがまだ存在しないためトリガ抵触とZabbixは判断
5) 14:27:00 4)の結果としてevent生成⇒eventへ、eventid=186323のレコードを生成(障害)。clockはシステム時刻を設定
6) 3)で遅延していた書き込みが終了(historyへ監視データ書き込み)
7) トリガチェック処理にてhistoryをチェック、監視正常であることを確認⇒eventにeventid=186324のレコードを生成。clockはhistoryの時刻を設定

以下想定で推測してみました。
a)eventレコードの生成処理は、clockとしてhistoryのタイムスタンプを使用する。
b)ただし、nodataのような原理上historyにレコードが存在しないトリガであれば、システム時刻を使用する。

コメント表示オプション

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

noda()のチェックは、30秒ごとに実施されます。

恐らく、14:27:00にnodata()のチェックを行った時に、14:26:39の
アイテムのデータがZabbixサーバーからデータベース上のhistory
に保存する処理が終了していなかったのでしょう。

そのため、14:21:39から5分経過しても値が取得できていないので、
トリガーのイベントが発生し、その後、14:26:39のアイテムのデー
タをZabbixサーバーが保存の処理を行おうとして、その際に条件式
の評価が再度行われ、トリガーの状態が正常に戻ったのだと思われ
ます。

複数のプロセスで、主にデータベースを介して各プロセスが情報の
連携を行っているので、必ずしもリアルタイムで各プロセスが同期
をとって動いているわけではありません。
キャッシュやキュー、データベースの状態やそのレスポンスなどの
影響を受けたことも考えられます。

ですので、アイテムの更新間隔が5分でnodata()の引数も5分という
設定は、タイミングによってはどれかのプロセスの処理が遅延する
だけで障害と誤検知してしまいかねない設定ですのでお勧めしませ
ん。

一応、Zabbixサーバーと監視対象の時計が合っていることを確認し
ておいた方が良いかもしれません。

ただし、ソースまでは確認していません。

ユーザー zab-SR の写真

tnk さん。ご回答ありがとうございました。

Zabbixとしての仕様通りの動作なんですね。
了解しました。

以下アドバイスいただいた通り、nodataの引数は他条件にもよりますが、更新間隔×2ぐらいがよさそうですね。

「アイテムの更新間隔が5分でnodata()の引数も5分」

今後は留意するようにいたします。
ありがとうございました。

【補足】以下はソースを気軽に読めるようになったら、別途確認しておきます。

a)eventレコードの生成処理は、clockとしてhistoryのタイムスタンプを使用する。
b)ただし、nodataのような原理上historyにレコードが存在しないトリガであれば、システム時刻を使用する。