Amazon SQS の ApproximateAgeOfOldestMessage とは何なのか？

2020-05-21

SQS には ApproximateAgeOfOldestMessage という、queue に存在する最も古いメッセージの、queue に入ってからの経過時間に関するメトリクスがあります。例えば queue の処理が遅延していることを検知したい場合、ApproximateNumberOfMessagesVisible よりも良い指標となる場合があります。ただ、このメトリクスの定義の詳細についてはドキュメントに載っておらず、ドキュメントに書かれている内容も正確さを欠くので実験を通して現在の挙動についてまとめてみました。

実験結果等を踏まえた ApproximateAgeOfOldestMessage の定義

結論から述べると、次のような定義と言えます。

メトリクスの対象メッセージは queue に存在するすべてのメッセージであり、invisible なものも含む
メトリクスの値は queue に存在するメッセージの age の最大値
- age は queue に入ってからの経過時間（秒）だが、何度も取得しては処理に失敗するようなメッセージはあるタイミングでリセットされる
3 回取得しても処理できなかったメッセージは age がリセットされる
- 再度 3 回取得しても処理できなかった場合は再度リセットされる
redrive policy が設定されている場合、メッセージが dead-letter queue に移る以外に、ApproximateAgeOfOldestMessage に与える影響はない
- dead-letter queue に移ったらメトリクスの対象から外れる
queue が inactive な場合はメトリクスを取得できない
- cf. Reporting Criteria: A non-negative value is reported if the queue is active.
- 0 という値が取得できるわけじゃないので注意

queue の処理の遅延を監視したい場合、visible なメッセージだけを対象とした ApproximateAgeOfOldestVisibleMessage も欲しくなりますね。

なお、ちょっと前までは SQS のメトリクスは 5 分間隔でしか取得できなかったんですが、半年前に 1 分間隔で取得できるようになりました。
cf. Amazon SQS Now Supports 1-Minute CloudWatch Metrics

ドキュメント上の ApproximateAgeOfOldestMessage の定義

参考までにドキュメントの定義について触れておきます。ApproximateAgeOfOldestMessage について、ドキュメントには次のように説明されています。

The approximate age of the oldest non-deleted message in the queue.

When the queue has a redrive policy, the message is moved to a dead-letter queue after the configured maximum number of receives. When the message is moved to the dead-letter queue, the ApproximateAgeOfOldestMessage metric of the dead-letter queue represents the time when the message was moved to the dead-letter queue (not the original time the message was sent).

When a queue doesn’t have a redrive policy, after the message is received three times (or more) and not processed, the message is moved to the back of the queue and the ApproximateAgeOfOldestMessage metric points at the second-oldest message that hasn’t been received more than three times.

Because a single poison-pill message (received multiple times but never deleted) can distort this metric, the age of a poison-pill message isn’t included in the metric until the poison-pill message is consumed successfully.

ざっくりと次のようなことが書かれています。

ApproximateAgeOfOldestMessage は queue の中の最も古い非削除状態のメッセージの大まかな age
redrive policy が設定されている場合、dead-letter queue の ApproximateAgeOfOldestMessage は dead-letter queue に移ってからの経過時間であり、元の queue にメッセージが送られた時間からの経過時間ではない
redrive policy が設定されていない場合、3 回メッセージを取得しても処理できなかった場合は queue の最後に戻され、ApproximateAgeOfOldestMessage は 2 番目に古いメッセージの経過時間が使われる
ポイズンピルメッセージ（決して削除されないメッセージ）の経過時間はメトリクスに含まれない

ポイズンピルメッセージという言葉が見慣れないですが、SQS の特徴について書かれているページにも説明が載っています。

Poison pills are special messages that can be received, but not processed. They are a mechanism used in order to signal a consumer to end its work so it is no longer waiting for new inputs, and is similar to closing a socket in a client/server model.

cf. https://aws.amazon.com/message-queue/features/#Poison-pill_Messages

要は consumer に終了処理をさせるためのメッセージですね。SQS にこんな機能があることを知らなかったんですが、どうやったら使えるんでしょう？
ポイズンピルメッセージは「何度取得しても意図せず処理に失敗するメッセージ」みたいな意味でも使われているケースがあるようですが、正式な意味は「consumer に終了処理をさせるためのメッセージ」だと思います。Akka でも PoisonPill オブジェクトの説明として次のように記述されています。

A message all Actors will understand, that when processed will terminate the Actor permanently.

cf. https://doc.akka.io/api/akka/2.6.5/akka/actor/PoisonPill$.html

ちなみに次の箇所ではポイズンピルメッセージが「何度取得しても意図せず処理に失敗するメッセージ」の意味で使われていそうです。

Using a dead-letter queue decreases the number of messages and reduces the possibility of exposing you to poison pill messages (messages that are received but can’t be processed).

cf. https://docs.aws.amazon.com/AWSSimpleQueueService/latest/SQSDeveloperGuide/working-with-messages.html#capturing-problematic-messages

実験

redrive policy が設定されている状態で処理に成功しないメッセージしか存在しない場合にどうなるか？

redrive policy が設定されていない場合については 3 回メッセージを取得しても処理できなかったメッセージの扱いについて言及されていますが、redrive policy が設定されているケースについては言及されていないので実験してみました。

まず次のように maxReceiveCount=6 で redrive policy を設定します。

% aws-owner aws sqs set-queue-attributes --queue-url $QUEUE_URL --attribute "$(cat <<JSON
{
  "RedrivePolicy": "{\"deadLetterTargetArn\":\"$DEAD_LETTER_TARGET_ARN\",\"maxReceiveCount\":\"6\"}"
}
JSON
)"

queue に対して決して処理しないメッセージを送り、queue をポーリングします。

require 'logger'
require 'aws-sdk-sqs'

QUEUE_URL = ENV['QUEUE_URL']

logger = Logger.new($stdout)
client = Aws::SQS::Client.new

resp = client.send_message(queue_url: QUEUE_URL, message_body: 'poison pill')

poller = Aws::SQS::QueuePoller.new(QUEUE_URL, client: client)
poller.poll(max_number_of_messages: 1, visibility_timeout: 120) do |msg, stats|
  if msg.body == 'poison pill'
    logger.info "Skip deleting a poison pill message"
    throw :skip_delete
  end
end

ログは次のとおりです。maxReceiveCount=6 なので、6 回ログが表示された後はメッセージが取得できなくなって何も表示されません。

I, [2020-05-20T16:58:24.525361 #19422]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:00:24.522334 #19422]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:02:24.517983 #19422]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:04:24.524871 #19422]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:06:24.530708 #19422]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:08:24.519484 #19422]  INFO -- : Skip deleting a poison pill message

CloudWatch メトリクスは次のように 3 回目の処理が終わったところで値がリセットされていることがわかります。dead-letter queue に移ったタイミングで 0 になっています。

また、visibility_timeout を 2 分間にしているので、invisible な間もメトリクスの対象になっていることがわかります。

redrive policy が設定されている状態で処理に成功しないメッセージと成功するメッセージが存在する場合にどうなるか？

redrive policy が設定されている場合に関しては 3 回処理に失敗すると 2 番目に古いメッセージの age が使われると説明されていたので、2 番目に古いメッセージの age がせいぜい 60 になるケースで試してみます。

まず次のように maxReceiveCount=6 で redrive policy を設定します。

% aws-owner aws sqs set-queue-attributes --queue-url $QUEUE_URL --attribute "$(cat <<JSON
{
  "RedrivePolicy": "{\"deadLetterTargetArn\":\"$DEAD_LETTER_TARGET_ARN\",\"maxReceiveCount\":\"6\"}"
}
JSON
)"

queue に対して決して処理しないメッセージを送り、その後 1 分間隔で通常のメッセージを送ります。通常のメッセージの処理には 1 分かけるようにします。

require 'logger'
require 'aws-sdk-sqs'

QUEUE_URL = ENV['QUEUE_URL']

logger = Logger.new($stdout)
client = Aws::SQS::Client.new

resp = client.send_message(queue_url: QUEUE_URL, message_body: 'poison pill')

Thread.new do
  loop do
    client.send_message(queue_url: QUEUE_URL, message_body: 'message')
    sleep 60
  end
end

poller = Aws::SQS::QueuePoller.new(QUEUE_URL, client: client)
poller.poll(max_number_of_messages: 1, visibility_timeout: 120) do |msg, stats|
  if msg.body == 'poison pill'
    logger.info "Skip deleting a poison pill message"
    throw :skip_delete
  end

  sleep 60
  logger.info "Processed a message successfully"
end

ログは次のとおりです。maxReceiveCount=6 なので、6 回 “Skip deleting a poison pill message” というメッセージが表示された後は同様のメッセージが表示されなくなっています。

I, [2020-05-20T17:56:05.754756 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T17:57:05.792496 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T17:58:05.884363 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T17:59:05.981248 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T17:59:06.087033 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T18:00:06.123487 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:01:06.208532 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:02:06.293467 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:03:06.394401 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:03:06.484093 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T18:04:06.522935 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:05:06.621126 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:06:06.715317 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:06:06.813482 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T18:07:06.840756 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:08:06.912046 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:08:06.943509 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T18:09:06.965144 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:10:07.056506 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:10:07.148053 #20763]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T18:11:07.170804 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:12:07.221868 #20763]  INFO -- : Processed a message successfully
I, [2020-05-20T18:13:07.371993 #20763]  INFO -- : Processed a message successfully

CloudWatch メトリクスは次のように 3 回目の処理が終わったところで値がリセットされていることがわかります。

redrive policy が設定されていない状態で処理に成功しないメッセージと成功するメッセージが存在する場合にどうなるか？

ドキュメントに書いてあるケースです。3 回処理に失敗すると 2 番目に古いメッセージの age が使われるはずです。そしてその 2 番目に古いメッセージというのは 4 回以上取得されていないメッセージです。

まず次のように redrive policy を削除します。

% aws sqs set-queue-attributes --queue-url $QUEUE_URL --attribute "$(cat <<JSON
{
  "RedrivePolicy": ""
}
JSON
)"

queue の処理に関しては「redrive policy が設定されている状態で処理に成功しないメッセージと成功するメッセージが存在する場合にどうなるか？」の場合と同様です。

require 'logger'
require 'aws-sdk-sqs'

QUEUE_URL = ENV['QUEUE_URL']

logger = Logger.new($stdout)
client = Aws::SQS::Client.new

resp = client.send_message(queue_url: QUEUE_URL, message_body: 'poison pill')

Thread.new do
  loop do
    client.send_message(queue_url: QUEUE_URL, message_body: 'message')
    sleep 60
  end
end

poller = Aws::SQS::QueuePoller.new(QUEUE_URL, client: client)
poller.poll(max_number_of_messages: 1, visibility_timeout: 120) do |msg, stats|
  if msg.body == 'poison pill'
    logger.info "Skip deleting a poison pill message"
    throw :skip_delete
  end

  sleep 60
  logger.info "Processed a message successfully"
end

ログは次のとおりです。redrive policy が設定されていないので 7 回以上 “Skip deleting a poison pill message” というメッセージが表示されています。

I, [2020-05-20T19:28:09.210417 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:29:09.257892 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:30:09.354137 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:31:09.451225 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:31:09.535374 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:32:09.565026 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:33:09.661985 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:34:09.760235 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:35:09.844092 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:35:09.934111 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:36:09.971633 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:37:10.075460 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:37:10.127019 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:38:10.161350 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:39:10.197314 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:39:10.342584 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:40:10.381388 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:41:10.474108 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:42:10.560997 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:43:10.644003 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:43:10.726587 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:44:10.774488 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:45:10.818390 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:46:10.911682 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:47:11.026187 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:48:11.114160 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:49:11.224786 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:49:11.259694 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:50:11.302322 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:51:11.407123 #23064]  INFO -- : Processed a message successfully
I, [2020-05-20T19:51:11.546611 #23064]  INFO -- : Skip deleting a poison pill message
I, [2020-05-20T19:52:11.570001 #23064]  INFO -- : Processed a message successfully

CloudWatch メトリクスは次のように 3 回目の処理が終わったところで値がリセットされ、6 回目の処理が終わったところで再度リセットされていることがわかります。

よってドキュメントに載っている次の内容は正確ではないと言えます。

the ApproximateAgeOfOldestMessage metric points at the second-oldest message that hasn’t been received more than three times

最初の結論で述べたように、次のように考えるとわかりやすいのではないでしょうか。

メトリクスの値は queue に存在するメッセージの age の最大値
- age は queue に入ってからの経過時間（秒）だが、何度も取得しては処理に失敗するようなメッセージはあるタイミングでリセットされる
3 回取得しても処理できなかったメッセージは age がリセットされる
- 再度 3 回取得しても処理できなかった場合は再度リセットされる