Laravel new
LaravelのロックのDynamoDBドライバで高負荷時にロックが解除されない不具合
こんにちは、ナカエです。
本日の記事は、とあるプロジェクトでLaravelのロックのDynamoDBドライバの実装に起因するバグに苦しめられたので、その備忘録です。
環境
- Laravel 9.34
背景・症状
当該プロジェクトでは、アプリケーションにおけるロックのドライバとして、Redis（AWS上ではElastiCache for Redis）の代わりにスケールの容易なDynamoDBに移行していました。
※ 高負荷になるとRedisのスケーリングはとても面倒です。
高負荷時のパフォーマンスチューニングのため負荷試験を行なっており、
- RDSでプリペアドステートメントに関係する特定のエラーが出た直後にロック待ちのタイムアウトが頻発するようになることが多い
- DynamoDBのテーブルの中身を確認したところ、ロック用のアイテム（DynamoDBのレコード相当）が残っている
- ある程度ログを仕込んだりしたがあまり目ぼしい情報がなく手づまり気味
という情報を負荷試験チームから共有され、調査を開始しました。
LaravelのDynamoDBドライバ周りのコードを読んでも特に問題があるように思えず、
- 実行時間タイムアウトなどの致命的なエラーやPHP-FPMのセグメンテーションフォルトでfinally節でのロック解除をすり抜けた説
- コンテナがグレースフルシャットダウンしていない説
- DynamoDBのスロットリング が起こっていた説
などの仮説を立てていましたが、ログから得られる情報とはいまいち合致しません。
原因の解明
より詳細な情報を得るために、Illuminate\Cache\DynamoDbLock・Illuminate\DynamoDbStoreを継承して拡張し、さらに詳細なロギングを仕込んで調査を行おうと再度コードを深掘りしていました。
DynamoDbLock::release()の実装はロックのアイテムに設定したownerの値が合致しなければfalseを返して失敗します。
Illuminate\Cache\Lock（DynamoDbLockの基底となる抽象クラス）
/**
* Release the lock.
*
* @return bool
*/
public function release()
{
if ($this->isOwnedByCurrentProcess()) {
return $this->dynamo->forget($this->name);
}
return false;
}
/**
* Returns the owner value written into the driver for this lock.
*
* @return mixed
*/
protected function getCurrentOwner()
{
return $this->dynamo->get($this->name);
}
Illuminate\Cache\Lock（DynamoDbLockの基底となる抽象クラス）
/**
* Determines whether this lock is allowed to release the lock in the driver.
*
* @return bool
*/
protected function isOwnedByCurrentProcess()
{
return $this->getCurrentOwner() === $this->owner;
}
Illuminate\Cache\DynamoDbStore
/**
* Remove an item from the cache.
*
* @param string $key
* @return bool
*/
public function forget($key)
{
$this->dynamo->deleteItem([
'TableName' => $this->table,
'Key' => [
$this->keyAttribute => [
'S' => $this->prefix.$key,
],
],
]);
return true;
}
$this->isOwnedByCurrentProcess()でGetItemによりロックのアイテムを取得- 取得できなかった場合もfalse。取得したアイテムとownerを比較し、一致しなければfalse。
- 一致した場合は DynamoDbStore::forget()の中でDeleteItemが呼ばれる
という処理順です。
ここでGetItemとDeleteItemで整合性が取れない可能性があるのではないかと思いつき、DynamoDbStore::get() の実装を見てここが怪しい事がわかりました。
/**
* Retrieve an item from the cache by key.
*
* @param string $key
* @return mixed
*/
public function get($key)
{
$response = $this->dynamo->getItem([
'TableName' => $this->table,
'ConsistentRead' => false,
'Key' => [
$this->keyAttribute => [
'S' => $this->prefix.$key,
],
],
]);
// 略
}
ConsistentReadがfalseのため、最新のItemが取得できていないのではという仮説です。
- ロック獲得待ち
- 指定したキーでロック獲得（PutItemで同じキーのitemが存在しない場合にitemを作成)
- コールバック処理
- 指定したキーでGetItemにより現在のitemを取得し、プロセスのownerと一致するか確認
- 一致した場合はDeleteItemで指定しのキーのitemを削除
4のGetItemでConsistentRead（一貫性のある書き込み）がfalseに指定されているということです。
DynamoDBの読み取り時の一貫性について、ConsistentReadがfalseの場合は結果整合性のある読み取り（Eventually consistent reads）となります。 結果整合性のある読み取りでは、最近書き込み完了した操作の結果が反映されないことがあると公式ドキュメントにもありました。
参考: DynamoDB の読み取り整合性 - Amazon DynamoDB
つまり4の読み取りで2で作ったItemが取れない可能性があるということです。
プリペアドステートメント関連のエラーの直後に問題が起こるのも、この仮説で説明可能です。
- 3でプリペアドステートメント関連のエラーが出てcallback内の処理がすぐ終わってしまう
- 2 -> 4 の間隔がとても短くなることで、ConsistentRead=falseの一貫性のない読み込みで2で作成したitemが取れずowner不一致判定になる
- 5のDeleteItemが走らない
- 2で作成したitemが消えないまま残ってしまう
- ロックが解除されないままになり、ロック待ちタイムアウトが頻発する
これは勝ったな、という事でGetItemとDeleteItemの不整合を解消しかつDynamoDBへのアクセスを減らすため、DeleteItem＋Condition Expression一発でownerの判定も行うようにした修正版ドライバを用意しました。
FixedDynamoDbStore
/**
* DynamoDbLock::block()内のrelease()でロック解放に失敗するケースがあるので修正版
*/
class FixedDynamoDbStore extends DynamoDbStore
{
/**
* @inheritDoc
*/
public function lock($name, $seconds = 0, $owner = null)
{
return new FixedDynamoDbLock($this, $this->prefix.$name, $seconds, $owner);
}
/**
* valueが同じ場合のみ削除
*
* @param string $key
* @param mixed $value
* @return bool
*/
public function forgetIfSameValue(string $key, mixed $value): bool
{
try {
$this->dynamo->deleteItem(
[
'TableName' => $this->table,
'Key' => [
$this->keyAttribute => [
'S' => $this->prefix.$key,
],
],
'ConditionExpression' => '#value = :value',
'ExpressionAttributeNames' => [
'#value' => $this->valueAttribute,
],
'ExpressionAttributeValues' => [
':value' => [
$this->type($value) => $this->serialize($value),
],
],
]
);
return true;
} catch (DynamoDbException $e) {
if (str_contains($e->getMessage(), 'ConditionalCheckFailed')) {
logs()->error(
'[DynamoDbStore Error] DeleteItem failed by value difference.',
[
'table' => $this->table,
'keyAttribute' => $this->keyAttribute,
'key' => $this->prefix.$key,
'valueAttribute' => $this->valueAttribute,
'value'=> $value,
]
);
return false;
}
throw $e;
}
}
}
上記およびDynamoDbLockを継承した FixedDynamoDbLock::release() の実装で FixedDynamoDbStore::forgetIfSameValue() を使うように変更しています。
修正版のコードを使った再度の負荷試験の結果、立てた仮説通りにエラーは解消されました。
今回は少しでも負荷を下げるためにDeleteItemとCondition Expressionを使う修正としましたが、環境変数の設定で、DynamoDbStore::get()におけるConsistentReadをtrueにもできるように変更するという手もあります。
ローカル開発環境または低負荷時の再現性のなさ
ローカル開発環境でDynamoDB Localを使ってもこのエラーは再現しませんでした。本物のDynamoDBと違いDynamoDB LocalはConsistentReadをfalseにしても、ほぼ強い一貫性を持つ読み取り相当になってしまいます。開発マシンのスペックをとんでもなく下げたりするともしかすると再現するかもしれませんが。
また、AWS上の環境でも低負荷の状態ではこのエラーを再現させることはできませんでした。高負荷時で書き込み後の読み取りにアイテムの状態が反映されるまでのレイテンシが長くなることが再現の条件となっていたと考えられます。
まとめ
高負荷時しか再現しないエラーだったこと、また初期からLaravelの実装を疑えなかったことで、かなりの苦戦を強いられました。 DynamoDBへの理解がもう少し深ければ早めに解決できたかもしれません。
今回の対象のLaravelのバージョンは9でしたが、おそらく最新のLaravelでも再現するはずなので、不具合とその対処をもう少し整理したのち、LaravelのGitHub Issueにも報告する予定です。
