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

はじめに

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

事象について

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

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

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

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

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

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

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

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

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

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

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

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

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

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