PostgreSQLのEXPLAINを読む

https://taityo-diary.hatenablog.jp/entry/2018/07/07/071928

https://speakerdeck.com/keiko713/explain-explain

過去のメモ

id:shiba_yu36 と眺めたメモ

問題のクエリを調べる

まずはどのクエリの何が問題なのかを調べる必要がある。これは、KibanaやNewRelicなどから読み取れることが多い気がする。この時、プレースホルダが使われている場合は、その値をなるべく同じように再構成した方が良い。

データベースでクエリを評価する

まずはpsqlコマンドなどでDBに接続する。接続するデータベースのホスト名が分からない場合は、Mackerelのdbロールを探して、ホストのメタデータを見るとEndpointに書いてある。

psql -U nobody --password -h $host mackerel3

または、更新系のクエリを実行したい場合は、スナップショットからインスタンスを作ってそちらに接続する。

• https://github.com/hatena/mackerel3/blob/develop/docs/useful-sql.md#%E6%8E%A5%E7%B6%9A%E5%85%88

クエリ評価

psqlコマンドなどでDBに繋いでクエリを実行する。この時に、EXPLAIN句をつけて実行する。

EXPLAIN (ANALYZE,BUFERS) SELECT * FROM xxx;

EXPLAIN のオプションには色々あるけど、おそらくこの辺りをよく使う。

• ANALYZE:実際に実行した結果の統計を出力する(省略すると計画だけ)

• BUFFERS:バッファの利用状況を出力する

• VERBOSE:計画についての追加情報を出力する

• https://www.postgresql.jp/document/9.2/html/sql-explain.html

おそらくこのような結果になるはず。(長いので一部省略)

mackerel3=> explain (analyze,buffers) select id, role_id, name, deleted, created_at, updated_at from role_metrics where role_id in (889771156637323264) and name in ('cpu.user.percentage', 'memory.cached');
                                                                                                                                         QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on role_metrics  (cost=44.35..91.15 rows=12 width=54) (actual time=0.033..0.035 rows=9 loops=1)
   Recheck Cond: ((role_id = '889771156637323264'::bigint) AND ((name)::text = ANY ('{cpu.user.percentage,memory.cached}'::text[])))
   Heap Blocks: exact=1
   Buffers: shared hit=31
   ->  Bitmap Index Scan on role_metrics_idx_role_id_name  (cost=0.00..44.35 rows=12 width=0) (actual time=0.027..0.027 rows=9 loops=1)
         Index Cond: ((role_id = '889771156637323264'::bigint) AND ((name)::text = ANY ('{cpu.user.percentage,memory.cached}'::text[])))
         Buffers: shared hit=30
 Planning time: 0.177 ms
 Execution time: 0.065 ms
(9 rows)

この結果から

• プラン演算子(Seq Scan, Index Scan, Bitmap Index Scanなど)
• 取得した行数
• キャッシュヒット数

などがわかる。この資料が詳しい。

• https://www.postgresql.jp/sites/default/files/2016-12/Explain%E8%AA%AC%E6%98%8E%E8%B3%87%E6%96%99%EF%BC%88%E7%AC%AC20%E5%9B%9E%E3%81%97%E3%81%8F%E3%81%BF%E5%8B%89%E5%BC%B7%E4%BC%9A%EF%BC%89.pdf

costとactual time

cost= の値は計画時点のコスト、actual time=が実際の実行結果を表す。actual timeはANALYZEオプションを追加しないと出力されない。

exact

exactモードとlossyモードがある。Bitmap Index Scanのビットマップサイズがメモリから溢れるとlossyモードに切り替わるらしい。

• https://taityo-diary.hatenablog.jp/entry/2018/07/07/071928

loops, width

loopsは副計画ノードを実行した回数。actual timeは1回あたりの時間なので、これが1以上の場合は乗算して実コストを計算する。らしい。widthはよく分からなかった。

• https://www.postgresql.jp/document/10/html/using-explain.html

costが異常に高いのは

(cost=44.35..91.15 rows=12 width=54) (actual time=0.033..0.035 rows=9 loops=1)

costに比べてactual timeが小さすぎるけど、これはPostgreSQLの内部を知らないと無理そう。