よく知らないアプリケーションの性能と戦う、という状況(再掲)
私が設計したわけでもなく開発したわけでもなく、レビュー参加とかで辛うじて全体はわけるけど、いまからソース見る時間もないし、開発した方は性能面の対処が覚束ない。突然性能面で火を噴いてなぜか自分が召喚されて2~3時間でどうにかしたい、という闇な状況にどういうふうに対応していたっけ自分、というのを経験則100%で書いてみようと思います。
前編・中編はこちら。
よく知らないアプリケーションの性能と戦わないといけないときの防衛術（前編）
https://qiita.com/nfujita55a/items/3760cd099ca890f5a4d4
よく知らないアプリケーションの性能と戦わないといけないときの防衛術（中編）
https://qiita.com/nfujita55a/items/555350e61b73db3a2b8c
この後編は道具の紹介(DBMS-PostgreSQLが例)です。、前編で特定した これがヤバそうというプロセスがPostgreSQLと特定できた後にどうしていたか を書いてみました。
……変なところもあると思うので、ご指摘お待ちしております。
vmstat と pg_stat_activity
まずは性能の問題が発生している PostgtrSQL サーバーにログインし vmstat を実行します。
例えば、4コアのサーバーでパーティションが「/」だけ切られててこんなふうになっていたら、
$ vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system------ ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
3 2 1396644 138700 7968 6263976 0 0 35840 4096 2583 579 40 1 56 2 0
1 1 1396644 125812 7964 6249224 0 0 5676 3584 18565 32282 11 9 55 25 0
1 1 1396752 146988 7952 6226776 0 0 5644 4204 26412 47005 12 11 56 21 0
1 1 1396752 139160 7952 6235068 0 0 7168 4096 25600 45379 11 11 55 23 0
1 1 1396752 131488 7964 6242316 0 0 6896 65224 22011 38559 12 10 51 26 0
0 2 1396752 127456 7964 6246276 0 0 2980 4096 9311 14309 20 4 52 24 0
2 1 1396752 120512 7964 6253204 0 0 6444 3080 13579 22878 8 7 61 25 0
0 2 1396852 131960 7964 6241440 0 0 15760 4196 14203 23189 9 7 64 21 0
2 1 1396852 125560 7964 6248624 0 0 6216 3584 11858 19502 8 6 63 24 0
2 2 1396852 137848 7956 6227964 0 0 6516 9180 7363 7245 23 3 50 25 0
1 1 1396852 142536 7944 6197020 0 0 8552 4112 7081 3443 24 4 41 32 0
- procs の b が0になるタイミングがない。
- bi, bo もそこそこある。
- CPU の wa が 25手前 をウロウロしている。CPUが4つあってもディスクは1つなのだから、25%は実際のところ100%。
- CPU の us+sy は50に達さず、id（アイドル）に空きがある。
と分かるので「ディスクがボトルネック」(この流れもよくある)と判断できます。
次に、なぜDBMSはディスクを読み書きするような処理をしているのか知りたいわけで、ディスクがボトルネックでもそうでなくても pg_stat_activity で、「現在、PostgreSQLに発行されているクエリは何か」を調べます。
※横に長いです。実際の結果を改変した例なので数値がおかしいのはご容赦を
$ psql -U hoge hogedb
> select * from pg_stat_activity
datid | datname | pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query | backend_type
-------+----------+-------+----------+----------+------------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------+-----------------+---------------------+--------+-------------+--------------+----------------------------------------------------------------------------------------------------------------+---------------------
| | 8192 | | | | | | | 2018-11-15 17:50:25.242567+09 | | | | Activity | AutoVacuumMain | | | | | autovacuum launcher
| | 8194 | 10 | postgres | | | | | 2018-11-15 17:50:25.242603+09 | | | | Activity | LogicalLauncherMain | | | | | background worker
16385 | hogedb | 23061 | 16384 | user01 | PostgreSQL JDBC Driver | 10.10.0.1 | | 34892 | 2020-12-25 22:41:15.277531+09 | 2020-12-25 22:41:21.194053+09 | 2020-12-25 22:41:27.858717+09 | 2020-12-25 22:41:27.858717+09 | IO | DataFileRead | active | 8542532 | 8542532 | insert into table1 (c1, c2, c3, c4) values ($1,$2,$3,$4) ON CONFLICT ON CONSTRAINT table1_pkey DO NOTHING | client backend
16385 | hogedb | 22372 | | | | | | | 2020-12-25 22:14:54.574566+09 | 2020-12-25 22:14:54.596588+09 | 2020-12-25 22:14:54.596588+09 | 2020-12-25 22:14:54.596589+09 | | | active | | 8542473 | autovacuum: VACUUM public.table1 | autovacuum worker
16385 | hogedb | 23063 | 16384 | user02 | PostgreSQL JDBC Driver | 10.10.0.2 | | 34896 | 2020-12-25 22:41:24.512955+09 | 2020-12-25 22:41:24.559247+09 | 2020-12-25 22:41:27.858132+09 | 2020-12-25 22:41:27.858132+09 | IO | DataFileRead | active | 8542533 | 8542532 | select c1, c2, c3, c4 from table1 where c2 <= $1 and c3 = $2 order by c1 desc | client backend
16385 | hogedb | 23067 | 16385 | user02 | PostgreSQL JDBC Driver | 10.10.0.2 | | 34825 | 2020-12-25 22:40:24.922965+09 | 2020-12-25 22:40:24.922965+09 | 2020-12-25 22:40:25.120965+09 | 2020-12-25 22:41:27.120965+09 | IO | DataFileRead | active | 8542534 | 8542532 | select c1, c2, c3, c4 from table1 where c2 <= $1 and c3 = $2 order by c1 desc | client backend
16385 | hogedb | 23069 | 16385 | user02 | PostgreSQL JDBC Driver | 10.10.0.2 | | 34814 | 2020-12-25 22:42:31.154757+09 | 2020-12-25 22:42:31.154757+09 | 2020-12-25 22:42:31.545407+09 | 2020-12-25 22:41:27.545407+09 | IO | DataFileRead | active | 8542535 | 8542532 | select c1, c2, c3, c4 from table1 where c2 <= $1 and c3 = $2 order by c1 desc | client backend
16385 | hogedb | 23072 | 16385 | user02 | PostgreSQL JDBC Driver | 10.10.0.2 | | 34925 | 2020-12-25 22:43:12.272667+09 | 2020-12-25 22:43:12.272667+09 | 2020-12-25 22:43:12.213544+09 | 2020-12-25 22:41:27.213544+09 | IO | DataFileRead | active | 8542536 | 8542532 | select c1, c2, c3, c4 from table1 where c2 <= $1 and c3 = $2 order by c1 desc | client backend
16385 | hogedb | 23064 | | | | | | | 2020-12-25 22:41:25.730477+09 | 2020-12-25 22:41:25.752676+09 | 2020-12-25 22:41:25.752676+09 | 2020-12-25 22:41:25.752677+09 | | | active | | 8542532 | autovacuum: VACUUM ANALYZE public.table2 | autovacuum worker
13806 | postgres | 23066 | 10 | postgres | psql | | | -1 | 2020-12-25 22:41:26.642323+09 | 2020-12-25 22:41:27.86806+09 | 2020-12-25 22:41:27.86806+09 | 2020-12-25 22:41:27.868105+09 | | | active | | 8542532 | select * from pg_stat_activity ; | client backend
| | 8190 | | | | | | | 2018-11-15 17:50:25.208832+09 | | | | Activity | BgWriterMain | | | | | background writer
| | 8189 | | | | | | | 2018-11-15 17:50:25.208563+09 | | | | Activity | CheckpointerMain | | | | | checkpointer
| | 8191 | | | | | | | 2018-11-15 17:50:25.209101+09 | | | | Activity | WalWriterMain | | | | | walwriter
見るのは、state が active の query です。これも複数回「select * from pg_stat_activity」を実行し、いつもactiveで出てくるSQLがないかを見ます。
いつも出てくるSQLのclient_addr(接続元IP)、query_start(クエリの開始時間)を参照し
- Webアプリケーションサーバーからの瞬時に終わるはずのクエリで、 query_start が十数秒前のプロセスがたくさん並んでいる（1つのSQL実行に時間かかったらおかしい。その分、サイト利用者は表示を待たされるから）
- 30分で通常終わるバッチ処理のサーバーから実行されるクエリが 1時間前 に開始
といったおかしなSQLを特定します。
問題のSQLの wait_event_type や wait_event も確認します。
この例だと
- wait_event_type = IO
- wait_event = DataFileRead
ですので、ディスクからのReadがボトルネック と分かります。このようにOS・DBMS両面を見て、ボトルネック箇所の裏付けを取ります。
必ず見ようよ実行計画
次は EXPLAIN文 の出番です。こんなふうなものです。あるバッチ処理のSQLの実行計画（を変えてみた）です
psql -U hoge hogedb
> explain 問題のクエリ(そこそこ長い)
Sort (cost=559316.53..559316.58 rows=19 width=8)
Sort Key: (function1(d.foo_count))
-> HashAggregate (cost=559311.19..559316.13 rows=19 width=8)
-> Result (cost=556681.39..559310.69 rows=100 width=8)
One-Time Filter: ('2020-12-09'::date = '2020-12-09 00:00:00+09'::timestamp with time zone)
-> Nested Loop (cost=556681.39..559285.69 rows=100 width=8)
-> Merge Join (cost=556680.82..558795.11 rows=108 width=21)
Merge Cond: ((l.bar_id = r.bar_id) AND (l.huga_index = r.index))
-> Sort (cost=62831.09..63392.21 rows=224450 width=12)
Sort Key: l.bar_id, l.huga_index
-> Nested Loop (cost=40.44..42881.93 rows=224450 width=12)
-> HashAggregate (cost=40.00..42.00 rows=200 width=4)
-> Seq Scan on t1 (cost=0.00..34.00 rows=2400 width=4)
-> Index Scan using ix_prefix_bazlog9c on prefix_bazlog9 l (cost=0.44..212.71 rows=149 width=16)
Index Cond: ((baz_id = t1.id) AND (bar_id = ANY ('{1234,1235,1236,1237}'::integer[])))
Filter: (piyo_time < '2020-12-19 00:00:00+09'::timestamp with time zone)
-> Sort (cost=493848.72..493993.02 rows=57719 width=25)
Sort Key: r.bar_id, r.index
-> Bitmap Heap Scan on prefix_barlog9 r (cost=386233.76..489284.08 rows=57719 width=25)
Recheck Cond: ((cust_foo_date = '2020-12-09 00:00:00+09'::timestamp with time zone) AND ((customer_send_type)::text = '1'::text) AND (bar_id = ANY ('{1234,1235,1236,1237}'::integer[])))
-> Bitmap Index Scan on ix_prefix_barlog9a (cost=0.00..386219.34 rows=57719 width=0)
Index Cond: ((cust_foo_date = '2020-12-09 00:00:00+09'::timestamp with time zone) AND ((customer_send_type)::text = '1'::text) AND (bar_id = ANY ('{1234,1235,1236,1237}'::integer[])))
-> Index Scan using foo_data_pkey_4 on foo_data d (cost=0.57..4.53 rows=1 width=17)
Index Cond: ((foo_data = '2020-12-09 00:00:00+09'::timestamp with time zone) AND ((foo_type)::text = '1'::text) AND ((baz_id)::text = (r.baz_id)::text))
EXPLAIN文では、問い合わせ自体は実行されず、実行計画だけが表示されます。EXPLAIN ANALYZE文であれば問い合わせが実行され、その所要時間と実行計画両方が表示されます。
上にあげた実行計画はそこそこ長いですが、実際のバッチ処理のSQLを実行計画かけたら、この程度の長さはよくあります。めげずに見ます
実行計画の見方自体はここでは説明をしませんが（すでに色々説明がある）、よくあるダメパターンは
- OLTP環境下において、たくさん発行されるシンプルなクエリで where 句の条件にかなうインデックスがなくて、大きなテーブルを高頻度で Full Scan (※)
- 集計などのクエリで Nested Loop の内部表（繰り返される側）が Full Scan だったり、効率が悪いインデックスを使用している
でしょうか。
※このような場合、vmstat で見ると、大きなテーブルがキャッシュに入りIOはさほど発生せず、us がぐんとあがることが多い。DBMSというディスクに読み書きするはずの仕組みがIOを発生させないのにCPUが高負荷なのはおかしい……そういう直感的な理解をしています。
$ vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system---- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
23 0 1396644 138700 7968 6263976 0 0 12 96 2583 579 98 0 2 0 0
19 0 1396644 125812 7964 6249224 0 0 245 84 18565 32282 97 0 3 0 0
24 0 1396752 146988 7952 6226776 0 0 644 4 26412 47005 98 0 2 0 0
52 0 1396752 139160 7952 6235068 0 0 168 96 25600 45379 99 0 1 0 0
54 0 1396752 131488 7964 6242316 0 0 896 24 22011 38559 95 3 2 0 0
23 0 1396752 127456 7964 6246276 0 0 980 16 9311 14309 98 0 2 0 0
できれば問答無用で仕掛けよう auto_explain
いや、pg_stat_actibity や explain する前に、ちゃんと auto_explain 仕掛けておこうよ、というのはその通りでございます。できれば、というか必ず自分が構築する際は auto_explain 仕掛けておきます。
そうすれば、○○秒以上時間がかかったクエリを実行計画とともに出力してくれます。
参考）PostgreSQL auto_explain モジュールの出力情報
https://qiita.com/bwtakacy/items/416dda4f3c4eb99cd006
足りないなら作れIndex
もし、明らかなIndexの欠落が見て取れて、サイトが落ちる寸前とかバッチが遅延しているとか急を要するなら、Index をその場で作成します。
Index作成したとき、他のクエリがそのテーブルに更新しようとすると待たされるので、
CREATE INDEX CONCURRENTLY sales_quantity_index ON sales_table (quantity)
と「CONCURRENTLY」をつければ、ロックを獲得せずIndexが作成されます。CONCURRENTLY には、作成時間がかかる、もしかすると、作成が失敗するかもしれない、というリスクがありますが、よく知らないアプリケーションでテーブルに更新の排他ロックかけるよりはずっとマシだ、と割り切ります。
参考）インデックスの同時作成
https://www.postgresql.jp/document/12/html/sql-createindex.html#SQL-CREATEINDEX-CONCURRENTLY
pg_stat_all_tables とダメ元ANALYZE
個人的に「ダメ元ANALYZE」と呼んでいるのですが、
- 昨日までは性能上の問題がなかった
- 今日になって突然、性能上の問題が発生した
というとき、統計情報（DBMSが持つテーブルのデータの分布情報）が古く、実行計画が非効率なものになっている可能性があります。
PostgreSQLの場合、pg_stat_all_tables であるテーブルの統計情報がいつ取得されたか、見ることができます。
$ psql -U hoge hogedb
> \x
Expanded display is on.
> select * from pg_stat_all_tables where relname = 'テーブル名';
-[ RECORD 1 ]-------+------------------------------
relid | 16392
schemaname | public
relname | hogehoge
seq_scan | 772
seq_tup_read | 14177993421
idx_scan | 44891175496
idx_tup_fetch | 31436711971
n_tup_ins | 13813258940
n_tup_upd | 0
n_tup_del | 13776931027
n_tup_hot_upd | 0
n_live_tup | 34048552
n_dead_tup | 1050799
n_mod_since_analyze | 684275
last_vacuum |
last_autovacuum | 2020-12-25 23:33:31.290387+09
last_analyze |
last_autoanalyze | 2020-12-25 23:38:07.036503+09
vacuum_count | 0
autovacuum_count | 4687
analyze_count | 0
autoanalyze_count | 15111
もし、
- おかしなSQLの目星がついていて
- そのSQLが使用するテーブルの "last_autoanalyze = PostgreSQLが自動で実行する統計情報取得"の取得日時が直近ではない
という場合、まずは
analyze verbose テーブル名
して改善するかを試す価値はあります。
※いざとなれば
$ psql -U hoge hogedb
analyze verbose
で全テーブル、統計情報取得し直すことも考えられるけど、これは避けたい（例外：自動統計情報取得が誤ってOFFに設定されていた場合）
やばそなやつはだいたいディスク
DBがボトルネックなのは分かっているけれど、なかなかどこを改善していいか分からない、そういうときの手段として vmstat や iostat でディスクがボトルネックと分かっているなら、ディスクをいいものにする、という選択もあります。
- オンプレミスなESX環境なら、いいディスク上(SAS SSDとか)に、VMのデータストアを移動してもらう（オンプレミス環境のインフラエンジニアさんに依頼）
が典型的でしょうか。
闇の魔術に対する防衛術 Advent Calendar 2020 25日目のエントリなのに、少し遅れてしまいました。みなさまお疲れ様でした。ありがとうございます。