この記事はBBSakuraNetworksアドベントカレンダー2023の17日目の記事です
https://adventar.org/calendars/8572

はじめに

発端はある時点からAPIのレスポンスが計測データ上で悪化する事象が起ったことでした。
その問題を解決するためにデータベースへのアクセスと、アプリケーションロジックの切り分けを行いました。
ISUCONをするというパフォーマンスチューニングの大会が存在しますが、これはISUCONをリアルな現場で行なった参戦記録になります。

事象について

まずどんな事件が起きたかを説明していきます。

特定の API のレスポンスタイムが普段の5倍ほどになっていた
計測データからはデータベースへアクセスしてデータ取得する処理の周辺で負荷が増えているように見える
データベースの負荷は特に上がっていない

これらの情報から切り分けを行なっていきます。

切り分け1ステップ目: データベース処理遅延の疑い

直接目に見えるデータはデータベースへのアクセス時間が増加していることを示しています。
このため、データベースへ直接アクセスして処理遅延が発生しているか確認しますが、特に遅延が発生していません。
一旦データベース自体の処理遅延については考慮しないようにします。

切り分け2ステップ目: 計測データについて

1ステップ目でデータベースが直接遅延している訳ではないことが分かりました。
データベース内で処理遅延していない場合、計測データに問題がある可能性があります。
そのため、どの時点が計測対象になっているかを確認する必要がありました。

こちらの図で[データ取得<=>DB間]の処理には問題がないので、[処理<=>データ取得]間で時間のかかる処理が存在しないか確認していきます。

切り分け3ステップ目: 全 API に影響を与える処理の特定

[処理]は実際は多くの処理を含んでおり、特定の処理ではないので、問題のある処理の特定が必要です。この観点でソースコードにデバッグログを差し込んで確認するなど、遅延した処理の特定を行いました。
そこからAPIリクエストの最初に行う暗号化データの処理の負荷が高まっていることを特定しました。

上記の例で言うと[デバッグログ1]の計測データに悪化が見られたことが分かりました。

暗号データの処理の内容を確認

被疑箇所の特定がで来ました。次に暗号データの処理で時間に影響する内容を特定していきます。暗号データで最も時間のかかる処理は暗号のデコード、エンコード処理です。このデコード、エンコード処理を行う被疑箇所に注目して、アプリケーションロジックを確認するとデータベースから取得して来たデータに対してデコード、エンコード処理をデータベースのレコード分行なっている処理が確認できました。

図は、全件データを取得して暗号データの処理を取得したデータ分行なっている当時の状況を表しています。

全件データの処理から必要なデータを絞り込む検討

全データから必要な処理を絞りこみ、必要なデータのみ処理の対象とすることがこのような問題の解決方法になります。
なので、全データを取得している処理からから必要なデータを絞りこみます。
このため、特定の識別子をデータベースのクエリに指定しました。

結果

以上の対応でAPIのパフォーマンスは劇的に改善されました。

データベースとアプリケーショロジックのアンチパターンappendix

ここで、今までに遭遇したデータベースとアプリケーションロジックのアンチパターンをまとめておきます。

N+1問題

有名なN+1問題です。

解決方法はクエリを分けないで一回で取得すること

データベースからの複数件取得から、ロジック側で負荷の高い処理を高頻度で行う

今回APIの処理劣化で遭遇した問題です。

データベースから大量の情報を取得する

いや、そんな大量のデータを気軽にSELECTするなよ問題です。
アプリケーションサーバのメモリかデータベースサーバのIOが死にます。

アプリケーションロジックのデータアクセス順序に関して

アプリケーションロジックから複数回にわたるデータアクセスがある場合、少ないデータに絞り込んでから次の処理でデータを渡す方が負荷が少ないが、最初にデータを絞り込まないで多いデータを次の処理に渡す問題です。
改善前

改善後

終わりに

ISUCONはリアルな業務でも役に立つコンテストであり、日々の業務に積極的に生かせる良いコンテストだと思います。
日々、システムパフォーマンスを上げるべくリアルな現場でISUCONをされている皆様と現場でのリアルISUCON話をまた共有したいです。