本文へ移動

CooLWJを検索

选择搜索范围,输入关键词后按回车。

言語

rabbitmqのコンシューマーが「理由もなく消える」

問題の背景:

9月1日17:12頃、導入担当者から、一部のデバイスが正常にアップグレードできない、コンソールから配信された指示を受信できないといった苦情が寄せられました。同僚が control プロジェクト(以下 control)のログを確認したところ、control がデバイスから報告されたシャドウ情報を受信しておらず、そのため指示を配信していないことが分かりました。control プロジェクトはデバイスと直接接続し、デバイスから報告された情報に基づいて、アップグレードやログの報告などの指示および設定情報を配信します。IoT の稼働開始前は、control はハートビートの報告に依存してデバイスの現在の情報を取得していましたが、IoT の稼働開始後はデバイスシャドウ情報に依存しています

によってデバイスの現在の情報を取得します。controlはデバイスのシャドウ情報を購読しますが、その情報はシャドウサービス(略称IoT)から転送されるもので、デバイスから報告されるシャドウ情報を直接受け取るわけではありません。具体的な流れは、以下の二つの図をご覧ください:

アプリケーション(control)がデバイスの状態を取得する

アプリケーション(control)がデバイスに命令を送信

 

control がシャドウメッセージを受信できないとわかると、私はすぐに rabbitmq のコンソールでメッセージの有無を調べ、二つのことを確認しました:1.デバイスがメッセージを送信したか 2.rabbitmq が正常か。以下の図1、図2は、当時撮影した rabbitmq コンソールの2枚の画面です。ここから図1機器からメッセージが送信されていることは明確に確認できるが、多くのメッセージがunacked(すでにコンシューマーに配信されており、コンシューマーがまだ ack を返していないだけであることを示しています。理論上は、しばらく待てば正常になります)のもので、具体的にどのキューにunackedのメッセージが滞留しているかは、こちらをご覧ください図2、“spacebridgeiot-shadow”まさにデバイスから報告されるシャドウ情報を受信するために使っているもので、メッセージがすべてキューに滞留していたのだから、controlに転送されていないのも筋が通る。しばらく観察するとunackedの数が0になったが、totalの総数には大きな変化がなかった。unackedのメッセージが再びメッセージキューへ戻って配信を待っているように見えた。案の定、数分後にはまた大量のunackedメッセージが現れ、さらに数分後にはそれらのunackedメッセージが再びキューへ戻った。control側では依然としてメッセージを受信していなかった。この時点でIoT側のログを確認すると、なんとシャドウメッセージが入ってきていなかった。rabbitmqのコンソールで「spacebridgeiot-shadow”このキューには、なんとコンシューマーがいなくなっていました。例えば図3に示すとおり。この時rabbitmqのログを確認すると、確かに次のようなエラー情報があった図4に示すように、rabbitmq が自ら接続を切断しました。

図1:rabbitmq の概要図

 

 

図2:rabbitmqキューの統計図

 

 

図3:spacebridgeiot-shadow 概要

 

 

 図4:rabbitmqのエラー情報

 

暫定的な解決策:

当時はすでに大量の苦情が寄せられていたため、「滞留しているメッセージを削除する」というかなり強引な解決策を採りました。削除すると、案の定正常に戻りました(備考:本番環境の問題は一刻も早く解決しなければなりません。ログを分析してから順序立てて解決する時間はなく、速さが求められます)。

 

RabbitMQ の技術識別マーク

非本番環境で問題を再現:

1.10.200.41.166 環境の rabbitmq のキュー「mirrorTestQueue」に大量のメッセージ(少なくとも数万件規模)を蓄積する

2.mirrorTestQueueのコンシューマーを停止し、メッセージが蓄積した後に再起動する

3.滞留が完了したら、コンシューマーを再起動

 

想定どおり、数秒の間に数千件のメッセージがコンシューマーにプッシュされ、数分続いた後、rabbitmq がコンシューマーとの接続を自ら切断しました。このとき、コンソールではキューのコンシューマーが見えなくなります。コンシューマーには自動復旧を設定してあるので、しばらくすると再び自動接続され、

しかし、すぐにまた接続が切れてしまい、本番環境で遭遇した問題とほぼ同じだった。いったい何がこの問題を引き起こしたのだろうか?正直なところ、当時はこれといった見当もつかず、ネットを一通り探しても、特に納得できる答えは見つからなかった(当時は問題の本質を捉えられておらず、検索キーワードが広すぎました)、その後

TCP層で何か問題が起きているのではないかと推測し、パケットをキャプチャして手がかりが見つかるか試すことにしました。すると、幸運にも見つかったのです。前置きはこれくらいにして、さっそく図をお見せします。

 

 

 13:06:25.643428より前はrabbitmqがコンシューマーにメッセージをプッシュし続けていましたが、13:06:25.643428の時点で、コンシューマーのtcpウィンドウがいっぱいになる状況が発生し始めました。その状態が約30秒続いた後、rabbitmqが自ら接続を切断しました(rstパケットを送信)。その後、コンシューマーが再接続しましたが、再びウィンドウがいっぱいになり、さらに約30秒続いた後、再度接続が切断されました。

 

かなり規則的に見え、毎回30s続くので、設定可能なパラメータのように感じる。大まかにまとめると「tcp full windowによりサーバー側が能動的に接続をrstし、しかも規則性がある」ということだ

今回は検索キーワードを変えて見つけました答え、rabbitmqには次の名前のパラメータがあるtcp_listen_options.send_timeout は書き込みタイムアウトを制御するパラメーターで、書き込みがタイムアウトするとtcpのRSTが発生します(https://github.com/rabbitmq/rabbitmq-java-client/issues/341)、変更して効果を試してみましょう:

1. 書き込みタイムアウトを10sに変更する

tcp_listen_options.send_timeout = 10000

 2.パケットをキャプチャして効果があるか確認する

 

 ウィンドウがいっぱいになってから接続が閉じられるまで、約10sかかります。

 

現象の振り返り:

rabbitmqのコンシューマー側でprefetchを設定していなかったため、rabbitmqが一度に過剰なメッセージを配信し、コンシューマー側の tcp ウィンドウが埋まりました。その結果、rabbitmq のtcp_listen_options.send_timeoutが発動し、この書き込みタイムアウトが一定のしきい値に達すると、rabbitmqがコンシューマーのtcp 接続を切断します。

 

究極の解決策:

        以前、メッセージを削除したのはやむを得ない対応でした。問題は解決したものの、あまりに強引だったので、もっと洗練された対処法を見つける必要があります。コンシューマーにプッシュされるメッセージが多すぎて tcp ウィンドウが埋まってしまうのなら、受信速度を工夫すべきです。rabbitmq に接続するときに、あまり大量に送らないよう伝えればよいのです。(以下の一節の引用元はhttps://blog.csdn.net/james_searcher/article/details/70308565)rabbitmqにはprefetchという属性があり、単一のコンシューマーが消費できる未確認メッセージ(unacked messages)の最大数を指します。どう理解すればよいのでしょうか?mqは各 consumerにバッファーを設け、そのサイズがprefetchです。メッセージを1件受信するたびに、MQはメッセージをバッファーに送り、そこからクライアントに送ります。ackメッセージを受信すると(consumer がbaseack命令を送信)、mqはバッファー内のスロットを1つ空け、新しいメッセージを追加します。ただし、このときバッファーが満杯なら、MQはブロック状態に入ります。より具体的に説明すると、prefetch値を10に設定し、consumerが2つあるとします。つまり、各consumerは毎回queueから 10 件のメッセージを先取りしてローカルに保持し、消費を待ちます。同時に、そのchannelのunacked数は20になります。Rabbitの配信順序は、まずconsumer1に10件のmessageを配信しきってから、consumer2に10件のmessageを配信するというものです。このとき新しいmessageを配信する必要があれば、まずchannelのunacked数が20に等しいかどうかを判定し、等しければconsumerには配信せず、messageはqueueに残ります。その後、いずれかのconsumerがメッセージ1件にackを返すと、unackedは19になります。Rabbitはどのconsumerのunackedが10未満かを判定し、そのconsumerに配信します。

 

コードで具体的に表すと

 

 

この値をどう評価すればよいのでしょうか。rabbitmq公式の記事に優れた説明があるので、ここでは詳しく述べません。私たちのシステムでは、現在20に設定しています。

https://www.rabbitmq.com/blog/2012/05/11/some-queuing-theory-throughput-latency-and-bandwidth/

 

 

おわりに:

私たちはrabbitmqの利用についてはまだ初心者の段階です。使う前に必ずrabbitmqのapiをよく読み、よく使うapiの使い方に慣れ、ローカル環境で十分に実験してください。


コメント

送信中

好きなテーマを選ぶ

選んだテーマはサイト全体に適用されます。