こんにちは、バックエンドエンジニアの江間です。
ある日、一通のメッセージが届きました。
ネタバレをすると、ある API が実行している SQL がスロークエリになっており、そのレスポンスが返ってくるまで DOM のレンダリングが行われていない事が原因でした。
この記事では、 New Relic Application Performance Monitoring (APM) を使ったスロークエリの特定と、それを実際にどうやって解決したのか、更に速度改善を行ってAPIの平均レスポンスタイムを約5.78倍にした話についてを書いていきます。
まずは当たりを付ける
該当のページは React でレンダリングを行っています。真っ白な画面になるということは DOM のレンダリングに時間がかかっている事が予想できます。
バックエンド視点で見ると、インフラ周りに問題はなく、 Fetch している API (アプリケーション側)が遅いのかな?と思えます。
次に、この現象が起こる特徴について
報告によると、プレスリリース配信数が多い企業の企業ページで、この現象が発生するらしい。
では実際にプレスリリース配信数が多い企業の企業ページで Fetch のタイミングを観察してみます。
レスポンスに4秒以上。流石にやばい。
このことから、プレスリリーステーブルを参照する API がスロークエリを叩いているのではないか?という当たりを付けることができました。
New Relic APM のどこを見るか
New Relic APM を使ったパフォーマンス問題の分析は公式ドキュメントに記載されています。
スロークエリトレースという便利な機能がありますが、 PR TIMES ではまだまだ多くのスロークエリがあるため、今回のようにピンポイントで情報が欲しい状況では、探し出すことが困難です。
そのためトランザクショントレースを使います。
APM > Transactions > 対象のAPI を選択し、 Transaction traces を見ます。
適当に選んだトレース結果から Trace details を見ます。
プレスリリーステーブル(t_release
)への SELECT 文がスロークエリとなっていることがわかりました。
スロークエリの発見
まず実行されたクエリを見てみます。先程のトランザクショントレースからデータベースアイコンを押します。
SELECT release_complete_date
FROM t_release
WHERE company_id = [企業ID] AND …
ORDER BY release_complete_date desc LIMIT 1;
このクエリは、プレスリリーステーブルから指定した企業の最初に配信したプレスリリースの配信日時を取得しています。
プレスリリーステーブルは、企業IDとプレスリリースIDを複合主キーとするt_release_primary_key
があり、primary key (company_id, release_id)
で定義されます。
また、プレスリリースの配信日時の INDEX としてt_release_release_complete_date_index
もあります。
テーブル構成(の中で必要な情報)はこちらです。
-- auto-generated definition
create table t_release
(
company_id integer not null,
release_id integer not null,
release_complete_date timestamp,
del_flg boolean default false,
…
constraint t_release_primary_key
primary key (company_id, release_id)
);
create index t_release_release_complete_date_index
on t_release (release_complete_date);
では New Relic で見つけたスロークエリに対して EXPLAIN を実行します。
プレスリリース数がそこまで多くない企業ではt_release_primary_key
が使われていて、 10 ms 以下で結果が返ってきます。
# EXPLAIN ANALYZE SELECT release_complete_date FROM t_release WHERE company_id = [企業ID] AND complete_flg = TRUE AND del_flg = FALSE AND stop_flg = FALSE AND release_media_list_only_flg = FALSE ORDER BY release_complete_date LIMIT 1;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=293.94..293.95 rows=1 width=8) (actual time=8.809..8.810 rows=1 loops=1)
-> Sort (cost=293.94..294.09 rows=60 width=8) (actual time=8.807..8.808 rows=1 loops=1)
Sort Key: release_complete_date
Sort Method: top-N heapsort Memory: 25kB
-> Index Scan using t_release_primary_key on t_release (cost=0.43..293.64 rows=60 width=8) (actual time=0.060..8.688 rows=652 loops=1)
Index Cond: (company_id = [企業ID])
Filter: (complete_flg AND (NOT del_flg) AND (NOT stop_flg) AND (NOT release_media_list_only_flg))
Rows Removed by Filter: 486
Planning time: 0.159 ms
Execution time: 8.834 ms
(10 行)
実行結果からt_release_primary_key
の INDEX を使ってcompany_id
からフィルタリングをし、その後release_complete_date
でソートしていることがわかりました。
対して、プレスリリース数の多い企業では、t_release_primary_key
が使われずにt_release_release_complete_date_index
というインデックスが使われています。
# EXPLAIN ANALYZE SELECT release_complete_date FROM t_release WHERE company_id = [企業ID] AND complete_flg = TRUE AND del_flg = FALSE AND stop_flg = FALSE AND release_media_list_only_flg = FALSE ORDER BY release_complete_date LIMIT 1;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.43..210.35 rows=1 width=8) (actual time=2200.277..2200.278 rows=1 loops=1)
-> Index Scan using t_release_release_complete_date_index on t_release (cost=0.43..512012.01 rows=2439 width=8) (actual time=2200.276..2200.276 rows=1 loops=1)
Filter: (complete_flg AND (NOT del_flg) AND (NOT stop_flg) AND (NOT release_media_list_only_flg) AND (company_id = [企業ID]))
Rows Removed by Filter: 632889
Planning time: 0.161 ms
Execution time: 2200.305 ms
(6 行)
どうやら、t_release_release_complete_date_index
インデックスを利用して ORDER BY をして WHERE 句の条件でフィルタリングしているようです。
その結果、 2200 ms かかってようやくデータが返ってきます。
解決方法
スロークエリに対する解決策として「インデックスを貼る」やり方が一般的であり、解決方法の一つとして複合 INDEX ((company_id, release_complete_date)
)を貼る方法があります。
ただし、このクエリで取得したいデータ(=最初に配信したプレスリリースの配信日時)はデータが変更されることがないという特徴があります。
(なのに、わざわざスロークエリを実行してデータを取ってきていた!)
そのため今回は「新たにカラムを追加して、そこにデータを保存する」やり方を選択しました。
-- 最初に配信したプレスリリースの配信日時
ALTER TABLE m_company ADD COLUMN first_released_date DATE;
カラムの追加は安全に無停止で行いたかったので、 NOT NULL 制約は付けずにいます。
カラムを追加したい対象のm_company
テーブルはレコードが大量にあるので、 ACCESS EXCLUSIVE ロックを取得する ALTER TABLE は慎重に行う必要がありました。
もし一つの ALTER TABLE で NOT NULL 制約を付ける場合、 DEFAULT 句を付ける必要があり、全件 UPDATE が行われて長時間のロックになります。
それを避けてバッチ処理などで段階的に UPDATE を実行したとしても、NOT NULL 制約を付けるタイミングで NOT NULL が可能であるかを全件検査するので、長時間のロックを引き起こす可能性があります。(参考)
これらのリスクを考慮して、first_released_date
カラムは NULL を許容したものとなっています。
アプリケーションの実装では、 API がリクエストされた時にfirst_released_date
カラムに値が入っている場合はそのまま返し、 NULL だった場合は一度その値をt_release
テーブルから取得して、m_company
テーブルに保存してからレスポンスを返します。
// 最初に配信したプレスリリースの日付カラムがNULLの場合
if (strlen($company->first_released_date) === 0) {
// プレスリリーステーブルから”最初に配信したプレスリリース”を取得
$first_press_release = PressReleaseRepo::getCompanyFirstReleaseByCompanyId($company_id, $pdo);
// ”最初に配信したプレスリリース”の配信日時を追加したカラムに入れる
$company->first_released_date = $first_press_release->release_complete_date;
// DBの更新処理をする(実際実行されるのは初回アクセス時だけ)
CompanyRepo::updateFirstReleasedDate($company, $pdo);
}
計測結果(スロークエリの解消)
App performance の結果を見てみます。
グラフに紫色で表示されるt_release
テーブルのスロークエリは解決出来ました 🙌
しかし、スピードはそこまで上がっていないようです。
考察(スロークエリの解消)
実は、このスロークエリの改善と同時に、別の部分も改修しました。
その際に SELECT を余分に呼び出してしまっているため、遅くなっているようです。
SQL | 実行時間 | 呼び出し回数(改修前) | 呼び出し回数(改修後) |
企業有効判定SQL | 29.021 ms | 1回 | 1回 |
企業情報取得SQL | 0.743 ms | 1回 | |
企業有効判定&企業情報取得SQL | 29.021 ms | 1回 |
※実行時間は psql から実行した結果であるので、New Relic の実行時間とは異なったデータになっています。
また、表を見ると「企業情報取得SQL」よりも「企業有効判定SQL」が遅いことがわかります。速度的にも INDEX が効いていないだろう事が予想が出来ます。
いい感じにスピードアップする
さて、ここから更に速度改善するために
- 不要な SQL の呼び出しを削除する
- 企業有効判定が効率的に行える INDEX を貼る
の2つの改修を行います。
不要な SQL の呼び出しを削除する
「企業情報取得SQL」を「企業有効判定SQL」と合わせた「企業有効判定&企業情報取得SQL」のSQLへ改修しました。しかし、「企業有効判定SQL」の呼び出しを消すことを忘れていました。
そのため、不要となった「企業有効判定SQL」を呼び出すコードを削除しました。
結果

倍近く速度改善されました!
企業有効判定が効率的に行える INDEX を貼る
「企業有効判定&企業情報取得SQL」の実際のSQLはこちらです。
SELECT m_company.*
FROM m_company
INNER JOIN m_company_user
ON m_company_user.company_id = m_company.company_id
WHERE m_company.company_id = [企業ID]
AND m_company.del_flg = FALSE
AND (m_company_user.regist_status = TRUE OR m_company.registmail_send = 1);
企業有効判定では、企業テーブル(m_company
)と企業ユーザーテーブル(m_company_user
)を確認しています。
企業テーブルと企業ユーザーテーブルは、企業IDで紐付いた親テーブルと子テーブルの関係です。しかし実際は外部キー制約も INDEX もありませんでした。
-- auto-generated definition
create table m_company_user
(
company_user_id serial
constraint m_company_user_pkey
primary key,
company_id integer default 0 not null,
…
);
そのため先程のクエリを EXPLAIN で調べてみると Seq Scan が行われている事が確認できます。
# EXPLAIN ANALYZE SELECT m_company.* FROM m_company INNER JOIN m_company_user ON m_company_user.company_id = m_company.company_id WHERE m_company.company_id = [企業ID] AND m_company.del_flg = FALSE AND (m_company_user.regist_status = TRUE OR m_company.registmail_send = 1);
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.29..4449.61 rows=99 width=1593) (actual time=2.787..21.173 rows=102 loops=1)
Join Filter: (m_company_user.regist_status OR (m_company.registmail_send = 1))
-> Index Scan using m_company_pkey on m_company (cost=0.29..8.31 rows=1 width=1593) (actual time=2.496..2.498 rows=1 loops=1)
Index Cond: (company_id = [企業ID])
Filter: (NOT del_flg)
-> Seq Scan on m_company_user (cost=0.00..4440.04 rows=101 width=5) (actual time=0.286..18.622 rows=102 loops=1)
Filter: (company_id = [企業ID])
Rows Removed by Filter: 89021
Planning time: 0.273 ms
Execution time: 21.255 ms
(10 行)
ということでm_company_user.company_id
に INDEX を貼ります。
CREATE INDEX ON m_company_user (company_id);
INDEX を貼った後、もう一度 EXPLAIN を実行します。
# EXPLAIN ANALYZE SELECT m_company.* FROM m_company INNER JOIN m_company_user ON m_company_user.company_id = m_company.company_id WHERE m_company.company_id = [企業ID] AND m_company.del_flg = FALSE AND (m_company_user.regist_status = TRUE OR m_company.registmail_send = 1);
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.71..19.63 rows=2 width=1606) (actual time=0.070..0.124 rows=10 loops=1)
Join Filter: (m_company_user.regist_status OR (m_company.registmail_send = 1))
Rows Removed by Join Filter: 6
-> Index Scan using m_company_pkey on m_company (cost=0.29..8.31 rows=1 width=1606) (actual time=0.011..0.013 rows=1 loops=1)
Index Cond: (company_id = [企業ID])
Filter: (NOT del_flg)
-> Index Scan using m_company_user_company_id_idx on m_company_user (cost=0.42..11.30 rows=2 width=5) (actual time=0.038..0.068 rows=16 loops=1)
Index Cond: (company_id = [企業ID])
Planning time: 0.558 ms
Execution time: 0.276 ms
(10 行)
無事に Index Scan が使われるようになりました。
実際の計測はこちら
かなり早くなりました 🙌
計測結果(最終)
New Relic
各改善後のAPIのレスポンスタイムを表にまとめました。
改善前 | スロークエリの改善 | 不要な SQL の 呼び出しを削除 | INDEX を貼る | |
1時間の平均レスポンスタイムの 最大値※1 | 336 ms | 223 ms | 114 ms | 68 ms |
平均レスポンスタイム※2 | 222 ms | 177 ms | 105 ms | 38.4 ms |
※1 下で計測した平均レスポンスタイムと同じ期間内での最大値になります。
※2 最大1週間となる任意の期間が対象です。改善のリリースまで1週間経っていない場合などは、より短い期間での計測になっています。
1時間の平均レスポンスタイムの最大値では約4.94倍、平均レスポンスタイムでは約5.78倍早くなりました!
Light House
Light House の結果はこちらになります。
Performance が 51 から 67 に向上しました!
APIが早くなったこともありますが、どうやらそれ以外にも今回作成した INDEX が上手く使われる様になって、全体的にパフォーマンスが上がったようです。
Network Timing
Light House の結果はこちらになります。
4.75 s もかかっていたレスポンスが 98 ms になりました!
レスポンスタイムが 100 ms 以下なので、十分なスピードになったかと思われます。
終わりに
今回はスロークエリから始まり、パフォーマンスの改善まで行いました。
スロークエリの発見やパフォーマンスの改善では New Relic を活用すると楽に行えるので、ご参考になれば幸いです。
最後に、バックエンドエンジニア(中途・インターン)を募集中です!
もしご興味がありましたらご応募下さい!