Share via

Azure Redis Cache で StackExchange.Redis がタイムアウトしたときの原因調査

  • Article

このポストは、2 月 10 日に投稿された Investigating Timeout Exceptions in StackExchange.Redis for Azure Redis Cache の翻訳です。

StackExchange.Redis では、同期処理の際に “synctimeout” という名前の構成設定を使用しています。既定ではこの値は 1000 ミリ秒に設定され、同期処理の呼び出しがこの設定で指定された時間内に完了しない場合はタイムアウト エラーが返されます。

このとき返されるエラー コードは、たとえば次のようになります。

Timeout performing MGET 2728cc84-58ae-406b-8ec8-3f962419f641, inst: 1,mgr: Inactive, queue: 73, qu=6, qs=67, qc=0, wr=1/1, in=0/0

上記のエラー コードの内容は下記のとおりです。

エラー コード

内容の詳細

inst

最後のタイム スライスで発行されたコマンドの数が 0 であることを示しています。

mgr

ソケット マネージャーが “socket.select” を実行していることを示しています。これは、OS に対して、実行すべき処理を抱えているソケットを知らせるよう要求していることを意味します。基本的に、ソケットは何らかの処理を実行しなければならないことを自分から把握することはないので、リーダーが積極的にネットワークから読み込みを行うことはありません。

queue

現在実行中の処理の総数が 73 個であることを示しています。

qu

実行中の処理のうち 6 個が未送信キューに存在することを示しています。これらの処理はまだ送信ネットワークに書き込まれていません。

qs

実行中の処理のうち 67 個が送信済みで、サーバーからの応答を待機していることを示しています。

qc

実行中の処理のうち 0 個が既に応答を受け取っていながら、完了ループで待機中であるため、まだ完了とマークされていないことを示しています。

wr

有効なライターが存在していること (つまり、未送信になっている上記の 6 個の処理が無視されていないこと) を示しています。数字はバイト数と有効なライター数を表しています。

in

有効なリーダーが存在せず、また NIC で読み込みが可能であったバイト数が 0 バイトであったことを示しています。数字はバイト数と有効なリーダー数を表しています。

 

 

 

原因調査の手順

タイムアウト エラーが返される原因の調査は、まず synctimeout で指定した時間内に処理が完了しない原因を特定することから始めます。

最初に確認すべき項目としては、次のようなものが挙げられます。

  • Azure Redis Cache とクライアントが同じ Azure リージョンにあるか。 Redis Cache が米国東部、クライアントが米国西部に存在しているために要求が synctimeout で指定した時間内に完了していない場合や、ローカルの開発マシンでデバッグ中の場合に、タイムアウトが発生する可能性があります。

キャッシュとクライアントは同じ Azure リージョンに配置することを強くお勧めします。また、異なるリージョン間で呼び出しを発行するような場合は、synctimeout に大きな値を設定します。

  • StackExchange.Redis の NuGet パッケージが最新のものであるか。

NuGet の https://www.nuget.org/packages/StackExchange.Redis/ (英語) のページを見ると、StackExchange.Redis が最新バージョンであるかどうかを確認できます。

コードは不具合の修正のために随時変更されており、新しいものほどタイムアウトが発生しにくくなっているので、最新バージョンを使用することで事態が好転する場合があります。

  • サーバーでネットワーク バウンドになっていないか。

次の表は、各サイズの Redis Cache でテストを実施して得られた帯域幅の最大値です (この結果は、IaaS VM から Azure Redis Cache のエンドポイントに向けて redis-benchmark.exe でテストした際に得られた値です。下記の値は保証されるものではありません)。

帯域幅バウンドの要求が存在する場合、処理に必要な時間が長くなり、タイムアウトの原因となることがあります。このような場合は大きめのサイズのキャッシュに移行し、十分な帯域幅を確保することをおすすめします。

キャッシュ名

キャッシュのサイズ

GET 数/秒 (1 KB の場合の値)

帯域幅 (Mbps)

C0

250 MB

610

5

C1

1 GB

12,200

100

C2

2.5 GB

24,300

200

C3

6 GB

48,875

400

C4

13 GB

61,350

500

C5

26 GB

112,275

1000

C6

53 GB

153,219

1000 以上

 

  • クライアントでネットワーク バウンドになっていないか。

クライアントでネットワーク バウンドになっていないかどうかを確認します。クライアントでネットワーク バウンドになるとボトルネックが発生し、タイムアウトの原因となることがあります。クライアントの VM のサイズを大きくしてキャッシュのサイズと速度を向上させると、事態が好転する場合があります。

  • サーバーまたはクライアントで CPU バウンドになっていないか。

クライアントで CPU バウンドになっているために要求の処理速度が低下して synctimeout の設定値を超過し、タイムアウトの原因となっていないかを確認します。VM のサイズを大きくするか、または負荷を分散すると事態が好転する場合があります。

また、サーバーで CPU バウンドになっていないかどうかをポータルで確認します。CPU バウンドになっている Redis に要求が発行されると、要求がタイムアウトする原因となることがあります。この場合の対処としては、データを複数のキャッシュに分割し、負荷を分散する方法があります。

  • サーバーでの処理に長い時間がかかるコマンドを使用していないか。

Redis サーバーでの処理に長い時間がかかるコマンドを使用している場合、タイムアウトの原因となることがあります。その例としては、多数のキーを含む MGET コマンド、KEYS * コマンド、記述が適切ではない lua スクリプトなどがあります。

redis-cli でクライアントと Azure Redis Cache を接続して SLOWLOG コマンドを実行すると、予想外に処理時間が長い要求がないかどうかを確認できます。このコマンドの詳細については、https://redis.io/commands/slowlog (英語) を参照してください。

Redis サーバーと StackExchange.Redis は、少数の大規模な要求の処理ではなく、多数の小規模な要求の処理に最適化されています。このため、データを細かく分割すると事態が好転する場合があります。

redis-cli.exe と stunnel を併用して SSL のエンドポイントに接続する方法の詳細については、こちらのブログ記事 (英語) を参照してください。

  • Redis サーバーの負荷が高くないか。

redis-cli クライアント ツールを使用して Redis のエンドポイントに接続し “INFO CPU” を実行すると、server_load の値を確認できます。server_load の値が 100 (最大値) の場合、該当する Redis サーバーが要求の処理により常時ビジーである (アイドル状態にならない) ことを示しています。

redis-cli から SLOWLOG を実行して、サーバー負荷が最大に達する原因となるような、処理に長い時間がかかる要求がないかどうかを確認します。

  • クライアント側にネットワークの一時的な中断を引き起こすイベントがなかったか。

クライアント (Web ロール/Worker ロール/Iaas VM) で、多数のクライアント インスタンスのスケール拡大/縮小や、新バージョンのクライアントのデプロイメントなどのイベントがなかったか、またはオートスケールが有効になっていないかを確認します。

マイクロソフトが実施したテストでは、オートスケールやスケール拡大/縮小により、送信側のネットワーク接続が数秒間ほど中断することがありました。StackExchange.Redis コードはこのようなイベントへの耐性があり、再接続を行います。しかし、この再接続の間に、キュー内の要求がタイムアウトすることがあります。

  • 小規模な要求を実行する前に大規模な要求が Redis Cache に存在し、タイムアウトの原因となっていないか。

エラー コードの “qs” というパラメーターは、クライアントからサーバーに送信されたが応答が得られていない要求の数を表しています。StackExchange.Redis では単一の TCP 接続を使用し、1 回につき 1 つだけ応答を読み込むため、この値の数は増加し続けます。最初の処理がタイムアウトしてもサーバーとのデータの送受信は止まらず、またこれが完了するまで他の要求はブロックされ、その結果タイムアウトが発生します。
ワークロードに対して十分なサイズのキャッシュを確保し、同時に大きなデータは細かく分割することで、タイムアウトの可能性を最小限に抑えることができます。

そのほかには、クライアントで ConnectionMultiplexer オブジェクトのプールを使用し、新しい要求を送信するときに「最少負荷の」ConnectionMultiplexer を選択するという解決策もあります。この場合、特定のタイムアウトにより他の要求もタイムアウトすることを回避できます。

  • RedisSessionStateprovider を使用している場合、再試行のタイムアウトの設定は適切であるか。

下のコードは RedisSessionStateProvider の設定例です。retrytimeoutInMilliseconds の値が operationTimeoutinMilliseonds の値以下の場合、再試行が実行されません。

次の設定の場合では、タイムアウトするまでに 3 回再試行が実行されます。この設定の詳細については、こちらのブログ記事 (英語) を参照してください。

 <add

name="AFRedisCacheSessionStateProvider"

type="Microsoft.Web.Redis.RedisSessionStateProvider"

host="enbwcache.redis.cache.windows.net"

port="6380"

accessKey="…"

ssl="true"

databaseId="0"

applicationName="AFRedisCacheSessionState"

connectionTimeoutInMilliseconds = "5000"

operationTimeoutInMilliseconds = "1000"

retryTimeoutInMilliseconds="3000"/>

 

  • used_memory_rss の値が used_memory の値よりも大きくなっているか。

redis-cli.exe でキャッシュに接続して Redis の INFO コマンドを実行すると、下記のようなメモリ割り当てに関する情報が出力されます。

used_memory_rss: OS から見た Redis に割り当て済みのバイト数 (Resident Set Size)。

used_memory: Redis が自身のアロケーター (標準の libc、malloc、jemalloc などのいずれか) を使用して割り当てたバイト数の合計。

cache size: 作成されたキャッシュのサイズ (この例の場合は 26 GB)。

削除ポリシーが設定されている場合、used_memory がキャッシュのサイズに達すると Redis はキーの削除を開始します。

used_memory_rss の値は少しだけ used_memory よりも大きい状態が理想的です。used_memory_rss の値が used_memory の値と比較して大きすぎる場合、メモリが内部または外部に断片化されています。逆に used_memory_rss の値が used_memory よりも小さすぎる場合、Redis のメモリの一部が OS によりスワップされています。これは、大きなレイテンシが発生する原因となる場合があります。

Redis はメモリ ページへの割り当てのマッピングを制御できないため、used_memory_rss の値が大きすぎると、メモリ使用量の一時的な急増が発生しやくなります。

Redis がメモリを開放すると、そのメモリはアロケーターに返されます。その後、アロケーターがメモリを OS に返す場合と返さない場合があります。そのため、used_memory の値と OS によってレポートされるメモリ消費量は異なることがあります。この差分は、使用されていないメモリを Redis が解放した後、そのメモリが OS に返されていない場合に発生します。この詳細については、https://www.redis.io/commands/info (英語) を参照してください。

マイクロソフトでは、断片化が発生しているときのシステムの挙動を改善する複数の変更をテストしていますが、現時点ではまだリリースされていません。さしあたっては、下記の対処によりこの問題を軽減することができます。

  • キャッシュをアップグレードしてサイズを大きくし、システムでメモリ制限に到達しないようにする。
  • キーに有効期限を設定して、古いデータが先行して削除されるようにする。
  • Redis の “INFO” コマンド (英語) を監視する。特に used_memory_rss の値に注意します。この値がキャッシュのサイズに近付いた場合、パフォーマンスの問題が発生しやすくなります。データをメモリ使用率の低い複数のキャッシュにシャード化するか、またはキャッシュのサイズをアップグレードすると事態が好転する場合があります。

お問い合わせ

以上の対策を行っても問題が解決されない場合、https://azure.microsoft.com/ja-jp/support/options/ で [サポートの要求] をクリックしてサポート チケットを発行してください。なお、原因の調査には次の情報が必要ですので、サポートまでお伝えください。

  1. キャッシュ名
  2. キャッシュのサイズ
  3. エラー発生日時 (タイムゾーンもお伝えください)
  4. 完全なスタック トレースを含む例外メッセージ
  5. クライアントのインスタンスの数と種類 (例: Web サイト、Web ロール、Worker ロール、VM など)
  6. デプロイされているクライアントのパブリック仮想 IP (VIP) アドレス
  7. StackExchange.Redis のバージョン (必要に応じて Microsoft.Web.RedisSessionStateProvider のバージョンもお伝えください)
  8. ConnectionMultiplexer オブジェクトの構成と使用方法がわかるようなコード スニペット、および 1 つの ConnectionMultiplexer インスタンスを複数のプロセスで共有しているかどうか
  9. キャッシュ サービスとクライアントが存在するリージョン
  10. エラー発生時前後にクライアントで何らかの変更を行ったか、多数のクライアント インスタンスのスケール拡大/縮小や新バージョンのクライアントのデプロイメントを実行したか、またクライアントのオートスケールが有効になっているか
  11. インシデント発生前と発生中の CPU 使用率
  12. インシデント発生時にすべての要求で高いレイテンシやタイムアウトが発生したか、または一部の要求のみで発生したか
  13. クライアント間で不具合がどのように拡散したか (それぞれで均等であったか、またはすべてが単一クライアントで起こったか)
  14. キャッシュへの書き込みデータまたはキャッシュからの読み取りデータのサイズ
  15. クライアントの synctimeout および connectiontimeout の設定値