はじめに

こんにちは、レバレジーズ株式会社 teratailチームリーダーの竹下です。

弊社では、サーバーをTypeScriptで実装しており、O/R MapperにはTypeORMを使用しています。
今回は、TypeORMの使い方を間違うと、サーバーが不定期にハングアップしてしまうという現象のご紹介です。
もし同じような現象が起きている方がいたら、ご参考になれば幸いです。

起きた現象

サーバーにはAWS Fargateを使っており、gRPCのサーバーとして立ち上がっているのですが、該当のサーバーが不定期に

CPUが張り付いた状態になるがヘルスチェックは正常なまま
一定時間すぎるとOutOfMemoryでタスクが死ぬ
自動で新しいタスクが立ち上がるが、1の状態にすぐなってしまう

ということが発生していました。深夜3時や4時などアクセスがほとんど無いようなときに発生していましたし、ヘルスチェックはタスクが死ぬまで正常なままですし、ログにも特にエラーが記録されていなかったので、調査が難航していました。

原因

一番の原因は、DBアクセスのコードでトランザクションを開始した中で更に新しくコネクションを取得しようとしていたことでした。そのコードによりハングアップ状態となり、サーバーで処理が全く行われないという状態になっていました。少し複雑な条件のため、ステップを踏んで説明していきたいと思います。

裏側で起きていたこと

実際の現象の裏では次のようなことが発生していました。

原因となるコードが存在するAPI endpointにアクセスが集中(偶然 or クローラーなどがアクセスするページに存在)
ハングアップが発生し、リクエストをうけつけるが処理が途中で止まっているため、ログ等も出ずにレスポンスを永久に返さない状態に
リクエストがたまることでメモリ使用量が増えていき、メモリの限界まで来るとOutOfMemoryが発生しタスクが死ぬ
Fargateがタスクを新しく起動する

ということが繰り返される状態でした。

ハングアップする条件

問題の発生は次の条件が重なったために起きていました

DBのTransaction内で更に新しいコネクションを取得しようとしているコードが存在する
ConnectionPoolを利用しており、プールにコネクションが残っていない場合に永久に(または長時間)ブロックする
問題のあるコードが同時並列でConnectionPoolのmaxサイズ以上に実行される

なお、上記の条件を満たすだけでこのバグは発生するため、言語、フレームワーク関わらず発生する可能性があります。

問題のコード

擬似コード

for(let i = 0;i < 10; i++) {
  startTransaction(async (tr) => {
    const conn = await getConnection() // <= ここが問題
  })
}

再現するサンプルコードをgithubのこちらのRepositoryに用意しました。実際に動かしてみたい場合は、こちらをご参考に。

何をやっているかと言うと、
ConnecttionPoolののSizeを10としたときに、10並列でDBへのアクセスを発生させているのですが、それぞれのアクセスで

Transactionの開始
Transaction内で更に新しいコネクションを取得

だけのコードになっています。

通常だと10並列ぐらいなら何も問題なく終了するはずのコードですが、サンプルコードを実行するとログが途中で止まり一生終了しなくなります。
ハングアップは、Transaction内で新しくコネクションを取得する部分で発生します。

何が起きているか更に詳しく

並列実行数を、コネクションプールのサイズより小さくした場合にはハングアップすることはありません。
つまり、

Transaction開始時に、ConnectionPoolから1 Connection取得
それが10並列されると10 Connection取得され、ConnectionPoolの残Connection数が0になる
Transaction内でさらにConnectionを取得しようとするが、ConnectionPoolにConnectionが残っていないため、そこでブロック

ということが発生してしまっています。この状態になってしまうと、ConnectionPoolからConnectionを取得する部分すべてでブロックされてしまい、ほぼすべての処理が止まるという状態になってしまいます。

解決策

恒久対応

Transaction内で新しくConnectionを取得するコードを撲滅する

これ一択です。

暫定対応

しかし、このようなコードは各所に散らばっており、修正してもレビューやリグレッションテストなども必要なので、適用までに時間がかかります。
なので、暫定対応もいくつか記載しておきます。

ConnectionPoolでConnectionが取得出来ない場合に、比較的短時間でタイム・アウトするようにする
ConnectionPoolの上限を非常に大きくしておく
- アイドル時の維持するコネクション数の設定があるConnectionPoolならば、上限は大きくしておいても、そこまでパフォーマンスの影響は受けません
サーバー台数を増やすし、ハングアップしたサーバーは再起動/停止する
- 並列数が減ればこの現象は起きなくなるので、暫定対処としては十分だったりします
ConnectionPoolの使用をやめる

おまけ

なぜヘルスチェックは通っていた？

gRPCの前にはNLB(Network load balancer)を置いているのですが、TCPの疎通チェックだけとなるためgRPCのAPIが叩かれていなかったため、ハングアップしていることを検知できていませんでした。
ALBのヘルスチェックはちゃんとgRPCを叩いてくれるのですが、デフォルトでは存在しないAPIを叩き、Unimplementedのエラーが帰ってくることでヘルスチェックをしているので、同様に検知は出来なかったかと思います。