どのようにしてデータベース負荷を80%削減するのか
How I Reduced my DB Server Load by 80% by Richard Schneeman on
原著者の許諾を得て翻訳・掲載しています。
これまでWebアプリのクエリパフォーマンスを最適化してきましたが、それでもクエリ時間が15秒以上のランダムなスパイクが発生していました。そこでデータベースクエリのチューニングを始めました。まず、インデックス および Rack Mini Profiler を使用してホームページを高速化。それから高負荷なクエリを追跡して除去しました。 その結果、平均応答時間は約50ms、perc95は1秒未満と大幅に改善させることができました。しかし、まだ厄介な問題が残っていました。24時間のうちに、perc95の応答時間は15秒または30秒になり、短時間のタイムアウトが始まるのです。この記事では、これらの問題箇所を見つけて解決し、データベース負荷を80％削減させた方法を紹介します。
スパイクが発生したときの、ダッシュボード画面はこのようになります。
この一連のリクエストが非常に遅い理由を調べるために、メトリクスツールを使用しました。 今回は、Heroku の Scout アドオンでメトリクスを取得しています。 そしてリクエストの最後の12時間を表示するようにスケールを変更すると（デフォルトは3時間）、巨大なスパイクが見られました。そのときのページがこちらです。
アプリやデータベースに何が起きたのでしょう。Scout からの出力では、1つのクエリが完了するまでに約38秒かかったことが分かります。手動で同じページを訪問すると、すぐに読み込まれました。読み込みが遅くなる特定のページについては、特に怪しいところはありませんでした。
幸運にも私は Heroku で仕事をしていたため、データベースエンジニアの Slack ルームに飛び込み、そのようなパフォーマンスの低下を引き起こす要因について尋ねました。彼らは私の DB がどのような平均負荷を受けているのか尋ねました。私は standard-0 DB を使用しており、Heroku は 0.2 の負荷 を維持できると記載されています。私は Papertrail でログを開き、 load-avg を検索しました。
そして遅いリクエストの時間にこのエントリを見つけました：
Jun 29 01:01:01 issuetriage app/heroku-postgres: source=DATABASE sample#current_transaction=271694354
sample#db_size=4469950648bytes sample#tables=14 sample#active-connections=35
sample#waiting-connections=0 sample#index-cache-hit-rate=0.87073 sample#table-cache-hit-rate=0.47657
sample#load-avg-1m=2.15 sample#load-avg-5m=1.635 sample#load-avg-15m=0.915
sample#read-iops=16.325 sample#write-iops=0 sample#memory-total=15664468kB
sample#memory-free=255628kB sample#memory-cached=14213308kB sample#memory-postgres=549408kB0.2またはそれ以下の通常の平均負荷は問題ありませんが、私のアプリはなんと最大2.15までスパイクしていました！
私はすでにクエリ時間を最適化するのに時間を費やしていたので、この結果に驚きました。データベースエンジニアの1人は、このHeroku pg：extras CLI拡張 の pg：outliers コマンドの使用を提案しました。
実行環境が Heroku 上ではない場合は pg_stat_statements テーブル経由で同じデータにアクセスすることができます。
この拡張機能をインストールしてコマンドを実行すると、1つのクエリが合計実行時間の80％も占めていることがわかりました。
$ heroku pg:outliers
total_exec_time | prop_exec_time | ncalls | sync_io_time | query
------------------+----------------+-------------+------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
3790:50:52.62102 | 80.2% | 100,727,265 | 727:08:40.969477 | SELECT ? AS one FROM "repos" WHERE LOWER("repos"."name") = LOWER($1) AND ("repos"."id" != $2) AND "repos"."user_name" = $3 LIMIT $4
493:04:18.903353 | 10.4% | 101,625,003 | 52:09:48.599802 | SELECT COUNT(*) FROM "issues" WHERE "issues"."repo_id" = $1 AND "issues"."state" = $2画面が小さい方用：
SELECT ?
AS one
FROM "repos"
WHERE LOWER("repos"."name") = LOWER($1) AND
("repos"."id" != $2) AND
"repos"."user_name" = $3
LIMIT $4実に奇妙です。なぜなら、私はこのようなクエリを書いた覚えがありません。コードベースで LOWER SQL呼び出しを検索しましたが、何も見つかりませんでした。私は Papertrail に戻って、プロダクションのどこで呼び出されているのか確認しました。最初に見つかったのがこちらです：
Started POST "/repos" for 131.228.216.131 at 2017-06-29 09:34:59
Processing by ReposController#create as HTML
Parameters: {"utf8"=>"✓", "authenticity_token"=>lIR3ayNog==", "url"=>"https://github.com/styleguidist/react-
User Load (0.9ms) SELECT "users".* FROM "users" WHERE "users".
Repo Load (1.1ms) SELECT "repos".* FROM "repos" WHERE "repos".
(0.9ms) BEGIN
Repo Exists (1.9ms) SELECT 1 AS one FROM "repos" WHERE LOWER( $3 LIMIT $4
(0.5ms) COMMIT
(0.8ms) BEGIN
RepoSubscription Exists (4.3ms) SELECT 1 AS one FROM "repo_ns"."user_id" = $2 LIMIT $3
SQL (5.6ms) INSERT INTO "repo_subscriptions" ("created_at",
(6.1ms) COMMIT
[ActiveJob] Enqueued SendSingleTriageEmailJob (Job ID: cbe2b04a-d271
Redirected to https://www.codetriage.com/styleguidist/react-
Completed 302 Found in 39ms (ActiveRecord: 21.9ms)
Jun 29 02:35:00 issuetriage heroku/router: at=info method=POST path="/repos" host=www.codetriage.com request_id=5e706722-7668-4980-ab5e-9a9853feffc9 fwd="131.228.216.131" dyno=web.3 connect=1ms service=542ms status=302 bytes=1224 protocol=httpsわかりやすくするために Log tags を削除しています
少し長いですが、Repo Exists のすぐ隣にクエリがあります。そのエンドポイント（ReposController＃create）をチェックしたところ、いくつか疑わしいメソッドがありましたが、すべてがきちんとチェックアウトされています（例：LOWER で SQL呼び出しを行わない）。どこがいけないのでしょう？クエリはどこから来たのでしょうか？
それはモデルのこのラインから来ていました。この無害な小さな行が、私のデータベース全体の負荷の80％を占めていました。この validates は、同じユーザー名と名前で2つの Repo レコードが作成されないようにするための Rails の呼び出しです。データベースに一貫性を持たせる代わりに、オブジェクトにコミット・フックを挿入し、新しいリポジトリを作成して重複がないことを確認する前にデータベースにクエリを実行します。
そのバリデーション処理を追加したとき、私はそれをあまり考えませんでした。バリデーションを見ても、高負荷の原因であるとは信じ難いです。結局のところ、約 2,000 の repos があるので、理論的には約2,000回しか起こらないはずですよね？
この疑問を解決するために、私はログを見直し、別の場所に同じSQLが呼び出されているところを見つけました。
Jun 29 07:00:32 issuetriage app/scheduler.8183: [ActiveJob] Enqueued PopulateIssuesJob (Job ID: 9e04e63f-a515-4dcd-947f-0f777e56dd1b) to Sidekiq(default) with arguments: #<GlobalID:0x00000004f98a68 @uri=#<URI::GID gid://code-triage/Repo/1008>>
Performing PopulateIssuesJob (uri=#<URI::GID gid://code-
User Load (10.4ms) SELECT
(35.4ms) BEGIN
Repo Exists (352.9ms) SELECT $3 LIMIT $4
SQL (3.7ms) UPDATE "repos"
(4.5ms) COMMIT
Performed PopulateIssuesJob (Job ID: 9e04e63f-a515-4dcd-947f-0f777e56dd1b) from Sidekiq(default) in 629.22msわかりやすくするために Log tags を削除しています
今回は、クエリは Web アクションではなく、バックグラウンドジョブからのものでした。調べると、バリデーションが作成時にのみ実行されておらず、レコードの更新で実行されていました。ユーザー名列または名前列が見つからなくても、念のためにデータベースに照会するのです。
すべての repos を繰り返し、時にはレコードを更新する夜間のタスクがあります。バックグラウンドタスクは、非常に長い Web リクエストとほぼ同じ時間に起こっていたことが判明しました。DB自身が通常の業務能力を上回って負荷を急増させ、その後、定期的な限られた時間の Web リクエストでデータベースの CPU 時間が枯渇していました。
私はすぐにそのバリデーションを削除し、代わりにデータベースに制約を加えるユニークなインデックスに置き換えました。
class AddUniqueIndexToRepos < ActiveRecord::Migration[5.1]
def change
add_index :repos, [:name, :user_name], :unique => true
end
end注：この修正は互換性がないので、私は既に一意でないエントリが作成されているケースを処理しています。コードベースを変更する必要はありませんでした。そうしないと、postgres のエラーを全て修正する必要があります。
これで、2つのレコードがデータベースレベルで同じユーザ名と名前の組み合わせを持つことはできず、レコードを更新するたびに Rails がクエリを実行する必要はありません。
Rails のバリデーションに競合があり、一貫性を保証することはできませんが、とにかくこれらのタイプのものをデータベースレベルで実行する方が良いでしょう。
SQL クエリの LOWER 部分がユニークなインデックスで表されていないことにお気づきでしょうか。私の場合、すでにデータをノーマライズしていたので、少しのロジックは冗長でした。
そのバリデーションを削除してユニークなインデックスを追加してから、私のアプリには30秒以上のリクエストスパイクはありません。そのデータベースは 0.2 load-avg 以下でハミングしています。
データベースが遅いとき、私たちは個々のクエリの実行速度を考える傾向があります。また、一つまたは複数のクエリがサイト全体をどのように遅くさせているか、と稀に考える事があります。
pg:outliers について知った後は、このようにインデックスを追加して負荷を減らすのに良い場所を見つけることもできました。
issuetriage::DATABASE=> EXPLAIN ANALYZE SELECT "repos".* FROM "repos" WHERE "repos"."full_name" = 'schneems/wicked' LIMIT 1;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------
Limit (cost=0.00..39297.60 rows=1 width=1585) (actual time=57.885..57.885 rows=1 loops=1)
-> Seq Scan on repos (cost=0.00..39297.60 rows=1 width=1585) (actual time=57.884..57.884 rows=1 loops=1)
Filter: ((full_name)::text = 'schneems/wicked'::text)
Rows Removed by Filter: 823
Total runtime: 57.912 ms
(5 rows)この全体的な実行時間は、マルチ秒の領域にはないが、素晴らしいことではありません。その連続スキャンはかなり高速ですが、自由ではありません。full_name にインデックスを追加すると速くなりました。同じクエリが 1ms 未満に戻ります。このようなインデックスは、DB負荷を軽減するのにも役立ちました。
要点をまとめると、
- データベースの負荷が高い場合は、一つの遅いクエリだけでなく、すべてのクエリが遅い可能性がある。
- Herokuで実行する場合は、CPU時間以上の時間を費やしているクエリを見つけるのに
pg：outliersを使う。他の場所で実行する場合はpg_stat_statementsを使うことができる。 - ログを使ってクエリを実行している場所を見つけ出し、クエリに時間がかかる理由を理解するために
EXPLAIN ANALYZEを実行する。 - クエリの入力は重要であり、大幅に異なるクエリパフォーマンスを提供する。
- 異常なクエリを避けるために、インデックスの追加、データの保存方法の変更、プログラミングロジックの変更をする。
- 可能な限り、アプリケーションコードの代わりにデータベースを使用してデータの一貫性を強化する。
後になって考えると、これは見つけて修正するのに非常に簡単なバグでした。必要なのはほんのちょっとした時間と適切なツールだけでした。私は数十年、おそらく何年もの間、毎日リクエスト時間に30秒以上のスパイクを毎日見てきましたが、面倒臭くてこれを掘り起こそうとしませんでした。1日に1回しか起こらなかったので、ユーザーへの影響はほとんどありませんでした。しかし適切なツールと私たちの優秀なデータベースエンジニアからの洞察力で、すぐに解決することができました。DBの最適化はまだ終わったわけではありませんが、目標を達成することができました。私のデータベースチューニングの旅をお読みいただきありがとうございます。
