エムスリーテックブログ

エムスリー(m3)のエンジニア・開発メンバーによる技術ブログです

90秒かかるDELETE文の原因を探る【PostgreSQL】

PostgreSQL

こんにちは！ デジスマチームの山田です。これはデジスマチームのブログリレー4日目の投稿です。

事業が成長してユーザー数やトランザクションが増加すると、それに比例して扱うデータの量やバリエーションも増加します。サービス規模の拡大に伴い発生する課題の1つにスロークエリがありますが、デジスマ診療においてもサービスの成長とシステムの健全性を維持するためにクエリの改善に日々向き合っています。

データベースの気持ちを知りたい

本稿ではそうした取り組みの1つとして、とあるDELETE文の改善の過程と、改善に至るまでに得られた調査のTipsを共有できればと思います。なお今回の事象は内部運用における特定のプロセスを最適化するための取り組みであり、利用いただいている方々の体験やサービス品質に影響を及ぼしたものではないことを申し添えておきます。
前提としてデジスマ診療はPostgreSQL互換のAmazon Auroraを利用しており、執筆時に利用しているメジャーバージョンは15です。他のバージョンでは仕様が異なる可能性がある点、また投稿向けにテーブル名やSQLを変更している点をご了承ください。

課題

問題となっていたSQLを次に示します。

DELETE FROM users WHERE id = ?;

ここでidはusersテーブルの主キーです。単純に考えればusersテーブルから1行削除するだけのSQLですが、このSQLの完了に90秒を要していました。試しにSELECT * FROM users WHERE id = ?というSQLを実行したところ0.1 ms程度で取得されたため、usersテーブルのスキャンに時間を要しているわけではなさそうです。
重要な情報として、usersテーブルのidは多くのテーブルから外部キーとして参照されていることがわかっています。そのため次の仮説を立てました。

  1. 削除時に外部キーとして参照している各テーブルのスキャンが行われており、そのスキャンに時間を要している
  2. 外部キーとして参照しているテーブルのON DELETEアクションによって削除/更新される行数が多く、時間を要している

SELECT文の調査であればEXPLAINのANALYZEパラメータをTRUEにして実行計画を確認したいところですが、今回はDELETE文です。usersテーブルは複数のテーブルから外部キーとして参照されているため、DELETE時に外部キー制約に違反した場合はエラーとなり実行計画が取得できません*1。削除できるデータを安全に用意するのにも手間がかかりそうだったため、今回は外部キーとして参照しているテーブルから泥臭く調べることにしました。
補足として、ANALYZEを利用するとトリガーされる外部キー制約の名前やその実行時間を確認できますが、その内部で実行されるSQLの実行計画までは（私の調べた限り）直接結果に表示されません。auto_explainモジュールを利用するとログから確認できますが、auto_explainを有効化するためにはデータベースの再起動が必要だったため今回は利用を見送っています*2。

調査

外部キーとして参照しているテーブル一覧を取得する

usersテーブルのidを外部キーとして参照しているテーブルがある場合、usersテーブルの行のDELETEやUPDATEの際には、その値に一致する行に対して参照テーブルのスキャンが必要になります。このとき参照行にインデックスがない場合、シーケンシャルスキャンが行われて全体の実行時間に影響を及ぼす可能性があります*3。
そこでまずは外部キー制約として参照するテーブルを調べることにしました。テーブルを1つずつ確認するのは労力がかかるため、可能ならSQLで調べたいものです。というわけでPostgreSQLのシステムカタログを利用した次のSQLを作成し、usersテーブルを外部キーとして参照するテーブルの一覧を取得しました。

SELECT
    con.conname AS constraint_name
    ,parent.relname AS parent_table_name
    ,child.relname AS child_table_name
    ,attr.attname AS child_column
    ,con.confdeltype
FROM
    pg_catalog.pg_constraint con
    JOIN pg_catalog.pg_class parent
    ON  con.confrelid = parent.oid
    JOIN pg_catalog.pg_class child
    ON  con.conrelid = child.oid
    JOIN pg_catalog.pg_attribute attr
    ON  attr.attrelid = child.oid
    AND attr.attnum = ANY(con.conkey)
WHERE
    con.contype = 'f'
AND parent.relname = 'users'
;

テーブルにインデックスが作成されているかどうかを確認する

上記で洗い出したテーブルをもとに、更にそのテーブルが外部キーに対してインデックスを作成しているかを調査します。例えば次のSQLを利用することで対象のカラムを含むインデックスが存在するかを大まかに確認できます。

SELECT
    *
FROM
    pg_catalog.pg_indexes
WHERE
    tablename = 'テーブル名'
AND indexdef LIKE '%' || 'カラム名' || '%'
;

複数列のB-treeインデックスにおいては指定するカラムの順序も重要です。検索条件（今回でいうと外部キーカラム）が先頭に指定されているかどうかを、次のSQLで確認しました*4。

WITH child_tables AS(
    SELECT
        con.conname AS constraint_name
        ,parent.relname AS parent_table_name
        ,child.relname AS child_table_name
        ,attr.attname AS child_column
        ,child.oid AS child_oid
        ,con.conkey[1] AS constraint_key
    FROM
        pg_catalog.pg_constraint con
        JOIN pg_catalog.pg_class parent
        ON  con.confrelid = parent.oid
        JOIN pg_catalog.pg_class child
        ON  con.conrelid = child.oid
        JOIN pg_catalog.pg_attribute attr
        ON  attr.attrelid = child.oid
        AND attr.attnum = con.conkey[1]
    WHERE
        con.contype = 'f'
    AND parent.relname = 'users'
)
SELECT
    c.constraint_name
    ,c.child_table_name
    ,c.child_column
    ,EXISTS(
        SELECT
            1
        FROM
            pg_catalog.pg_index pi
        WHERE
            pi.indrelid = c.child_oid
        AND pi.indkey[0] = c.constraint_key
    ) AS has_index
FROM
    child_tables c
;

このSQLの結果から外部キーに対してインデックスが作成されていないテーブルがいくつか見つかりましたが、インデックスを作成しても状況は改善せず、依然として90秒を要していました。

ON DELETE アクションによって削除/更新されるデータを確認する

被参照テーブルの行が削除される際には、参照テーブルに定義されたON DELETEアクションに従って動作します。例えばCASCADEが指定されている場合は削除された行を参照しているテーブルの行も自動的に削除されます。ON DELETEアクションは整合性を維持するための重要な機構ですが、1行しか削除していないように見えるDELETE文も実際には参照テーブルの多くの行に対して削除や更新が行われている可能性が考えられました。
そこでON DELETEアクションによって削除/更新される参照テーブルのデータを確認しました。デジスマでは日次のDBスナップショットをGoogle BigQueryに連携する仕組みがあるため、削除されたusersのidが特定できれば、前日に存在していたデータをBigQuery上で調査できます。
ここは各テーブルを地道に確認しただけなので詳細は割愛しますが、いくつかのusers.idを調べたところ削除/更新されるテーブルの行数が1件しかない場合でも90秒以上の時間を要していることがわかりました。

ここまでの結果を整理すると、
1. 参照テーブルの外部キーにインデックスは作成されている
2. ON DELETEアクションによる影響は小さそう

ということになります。どうしたものか...と少し行き詰まりを感じてGeminiに尋ねてみたところ、どうやらpg_stat_all_tablesやpg_statio_all_tablesという統計情報ビューが使えそうであることがわかりました。

pg_stat_all_tablesとpg_statio_all_tablesを確認する

pg_stat_all_tablesビューはテーブルへのアクセスの統計情報を表示します。またpg_statio_all_tablesビューはテーブルに対するI/Oの統計情報を表示します*5。実際にそれぞれのビューを見てみると、pg_stat_all_tablesからは特定のテーブルに対するシーケンシャルスキャンの回数（seq_scan）やその読み込み行数（seq_tup_read）、インデックススキャンの回数（idx_scan）などが確認できます。pg_statio_all_tablesからは特定のテーブルから読み取られたディスクブロック数やバッファヒット数を確認できます。
これらの情報を活用するため、次の3点のデータを取得しました*6。

  1. DELETE文が発行される前の情報
  2. DELETE完了後の情報
  3. DELETEの完了後、さらに少し時間を置いた後の情報

比較のイメージ

1から3までの各差分を取ることで、DELETEが実行されている期間におけるシーケンシャルスキャンの発生やディスクI/Oの傾向を知ることができます。該当の時間にはDELETE以外のオペレーションも実行されているため、3点で取得して比較しています。

これらの結果を確認したところ、articlesというテーブルのidx_blks_readの値が顕著に増加していることがわかりました。これは今回のDELETE文の実行がディスクから多くのインデックスブロックの読み込みを発生させていることを示唆しています。

オチ：結局はインデックス

どういうことだろう？ と思いながらarticlesテーブルのインデックスをもう一度確認します。

SELECT indexdef FROM pg_catalog.pg_indexes WHERE tablename = 'articles';

 CREATE INDEX articles_user_id_hogehoge_idx ON public.articles USING btree (user_id, hogehoge) WHERE (deleted_at IS NULL)
 CREATE INDEX articles_fugafuga_user_piyopiyo_idx ON public.articles USING btree (fugafuga_id, user_id, piyopiyo_id)
...

結果をよく見ると.....なんと存在していると思っていたインデックスは部分インデックスでした。部分インデックスが使用されるためにはその定義に含まれるWHERE句の条件（この場合deleted_at IS NULL）が問い合わせの条件に包含される必要があります。また、他にインデックスはありましたがuser_idを先頭に指定しないインデックスでした。問い合わせの条件に合致するカラムを先頭に持たないB-treeインデックスは、仮に問い合わせに使用されても効率的な絞り込みは期待できません。

確認のため、SELECT文の実行計画を取得します。

EXPLAIN ANALYZE SELECT * FROM articles WHERE user_id = ?;

Index Scan using articles_fugafuga_user_piyopiyo_idx on articles  (cost=0.56..484512.52 rows=9 width=1475) (actual time=75100.574..75216.192 rows=1 loops=1)
  Index Cond: (user_id = ?)
Planning Time: 19.534 ms
Execution Time: 75216.341 ms

Index Scanが行われていますが実行時間は75秒を要しています。articles_fugafuga_user_piyopiyo_idxは先程確認した通りuser_idを先頭に持たない複数列インデックスです。統計情報を確認した際にidx_blks_readの値が大きく増加していた事実と照らし合わせてもこれが原因の可能性が高そうです。

解決

articlesのインデックスを見直してuser_idが先頭に来るインデックスを作成したところ、90秒かかるDELETE文は150 ms程度まで改善されました。

終わりに

DELETE文の長時間実行は無事に解決できましたが、振り返ると調査は遠回りをしてしまったと反省しています。とはいえ複数の事実がつながって線となり原因が特定された瞬間は爽快で、少しデータベースの気持ちに近づけた気がしました。
またシステムカタログを活用することで調査を効率化できたり、調査のヒントを得ることができます。今後もこれらの知識を深め、サービスの成長に貢献していきたいです。

We are hiring!!

エムスリーではエンジニアを絶賛募集しています！ ご興味ある方は是非カジュアル面談等ご応募ください！

エンジニア採用ページはこちら

jobs.m3.com

カジュアル面談もお気軽にどうぞ

jobs.m3.com

エンジニア新卒採用サイトもオープンしました！

インターンもこちらから！

fresh.m3recruit.com

*1:なお当然ですが違反しなければ削除されるため、実行計画を確認する際はトランザクションを明示的に開始してROLLBACKするか、AUTOCOMMITを無効にするなどの配慮も有効かと思います

*2:利用方法についてはこちらを参照してください: F.4. auto_explain。次のスライドも非常に参考になりました: www.slideshare.net

*3:外部キー制約が付与されたカラムに対するインデックスは自動では作成されません。参考: 5.4. 制約

*4:このSQLはインデックスの先頭カラムが単一の外部キーと一致するかどうかを主に見ていますが、部分インデックスの考慮が抜けていました。この点を見落としていたため、その後の調査で遠回りすることになりました。

*5:参考: 28.2. 累積統計システム

*6:幸いにも問題のDELETE文が実行される時間がある程度わかっていたため、このような方法を取れました。