官人要杯咖啡吗? - PostgreSQL实时监测PLAN tree的执行进度 - pg_query_state
背景
当我们在数据库中执行一些比较大的查询，或者执行比较复杂的函数时，如果要知道执行到哪里了，预计还要多久。
怎么办呢？ 有方法得到吗？当然有。
目前PostgreSQL支持的是传统的SQL执行方法，将（nonutility）语句parser后，根据parser tree生成plan tree, 然后根据plan tree去执行里面的每一个NODE。
也就是说，我们实际上是可以随时查看plan tree，以及每个NODE的执行情况的（包括一些LOOP，例如 NEST LOOP JOIN）.
比如
postgres=# explain select * from a t1 join a t2 on (t1.id=t2.id) where t2.id between 1 and 10;
QUERY PLAN
---------------------------------------------------------------------------
Nested Loop (cost=0.55..17.50 rows=10 width=74)
-> Index Scan using a_pkey on a t2 (cost=0.28..2.48 rows=10 width=37)
Index Cond: ((id >= 1) AND (id <= 10))
-> Index Scan using a_pkey on a t1 (cost=0.28..1.49 rows=1 width=37)
Index Cond: (id = t2.id)
(5 rows)
这个QUERY包含了3个NODE，分别是index scan和nestloop.
得到进度条的原理如下
1. 生成执行计划(plan tree)
2. 按部就班的执行
3. 在执行过程中，我们可以跟踪执行的NODE，输出统计信息，打印QUERY的执行进度。
霸道插件：
https://postgrespro.com/docs/postgrespro/10/pg-query-state
pg_query_state插件
Oleg 的Postgrespro公司开源的一个插件pg_query_state就是用来干这个事情的。
可以观察SQL执行过程中动态变化的信息，包括hit, run tim, loop, memory开销等等。
用法举例
编译安装
git clone https://github.com/postgrespro/pg_query_state
cd pg_query_state
git checkout PGPRO9_6
cd xx/postgresql-9.6.1
patch -p1 < ../pg_query_state/custom_signals.patch
patch -p1 < ../pg_query_state/runtime_explain.patch
make && make install
cd pg_query_state
git checkout PGPRO9_6
make USE_PGXS=1
make USE_PGXS=1 install
cd $PGDATA
vi postgresql.conf
shared_preload_libraries = 'pg_query_state'
pg_query_state.enable = on
pg_query_state.enable_buffers = on
pg_query_state.enable_timing = on
pg_ctl restart -m fast
观察进度例子1
postgres=# create extension pg_query_state;
session a
postgres=# do language plpgsql
$$
declare
begin
for i in 1..100 loop
perform 1 from pg_class;
perform pg_sleep(10);
perform t1.relname from pg_class t1 join pg_class t2 on (t1.oid=t2.oid) where t1.oid::int8 <100000;
end loop;
end;
$$;
session b
postgres=# select pid,query from pg_stat_activity ;
pid | query
-------+------------------------------------------------------------------------------------------------------
36918 | do language plpgsql +
| $$ +
| declare +
| begin +
| for i in 1..100 loop +
| perform 1 from pg_class; +
| perform pg_sleep(10); +
| select t1.relname from pg_class t1 join pg_class t2 on (t1.oid=t2.oid) where t1.oid::int8 <100000;+
| end loop; +
| end; +
| $$;
37000 | select pid,query from pg_stat_activity ;
(2 rows)
多次调用pg_query_state，可以看到running time在不断的变化。
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
pid | frame_number | query_text | plan | leader_pid
-------+--------------+---------------------+-------------------------------------------------------------------------------------------------------------+------------
36918 | 0 | SELECT pg_sleep(10) | Result (cost=0.00..0.01 rows=1 width=4) (Current loop: running time=6362.586 actual rows=0, loop number=1)+|
| | | Output: pg_sleep('10'::double precision) |
(1 row)
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
pid | frame_number | query_text | plan | leader_pid
-------+--------------+---------------------+-------------------------------------------------------------------------------------------------------------+------------
36918 | 0 | SELECT pg_sleep(10) | Result (cost=0.00..0.01 rows=1 width=4) (Current loop: running time=8155.538 actual rows=0, loop number=1)+|
| | | Output: pg_sleep('10'::double precision) |
(1 row)
再来个复杂一点的
观察进度例子2
session a
postgres=# \dt+
List of relations
Schema | Name | Type | Owner | Size | Description
--------+--------+-------+----------+---------+-------------
public | sbtest | table | postgres | 3284 MB |
postgres=# \d sbtest
Table "public.sbtest"
Column | Type | Modifiers
--------+----------------+-----------------------------------------------------
id | integer | not null default nextval('sbtest_id_seq'::regclass)
k | integer | not null default 0
c | character(120) | not null default ''::bpchar
pad | character(60) | not null default ''::bpchar
Indexes:
"pk_sbtest_id" PRIMARY KEY, btree (id) WITH (fillfactor='100')
postgres=# select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
session b
可以看到，shared hit, runtiming,等都在变化
\x
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Merge Join (cost=0.87..1649962.89 rows=15535467 width=380) (Current loop: actual time=0.014..1785.903 rows=2046680, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Merge Cond: (t1.id = t2.id) +
| Buffers: shared hit=263742 +
| -> Index Scan using pk_sbtest_id on public.sbtest t1 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.006..305.380 rows=2046680, loop number=1)+
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=131871 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.004..469.854 rows=2046681, loop number=1)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=131872
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Merge Join (cost=0.87..1649962.89 rows=15535467 width=380) (Current loop: actual time=0.014..2648.177 rows=2882712, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Merge Cond: (t1.id = t2.id) +
| Buffers: shared hit=643548 +
| -> Index Scan using pk_sbtest_id on public.sbtest t1 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.006..453.747 rows=2882712, loop number=1)+
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=321774 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.004..723.293 rows=2882712, loop number=1)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=321774
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Merge Join (cost=0.87..1649962.89 rows=15535467 width=380) (Current loop: actual time=0.014..4218.101 rows=4407527, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Merge Cond: (t1.id = t2.id) +
| Buffers: shared hit=1288884 +
| -> Index Scan using pk_sbtest_id on public.sbtest t1 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.006..719.731 rows=4407527, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=644442 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..708465.44 rows=15535467 width=190) (Current loop: actual time=0.004..1183.861 rows=4407527, loop number=1)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=644442
leader_pid |
查询结束，结果返回中，这时显示的是backend is idle
postgres=# \set VERBOSITY verbose
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
INFO: 00000: state of backend is idle
LOCATION: pg_query_state, pg_query_state.c:552
(0 rows)
观察进度例子3
来一个嵌套循环
postgres=# set enable_mergejoin=off;
SET
postgres=# set enable_hashjoin=off;
SET
session a
postgres=# select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
session b
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Nested Loop (cost=0.43..8236166.16 rows=15535467 width=380) (Current loop: actual time=0.019..1297.191 rows=520855, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=2101162 read=6 +
| -> Seq Scan on public.sbtest t1 (cost=0.00..575579.67 rows=15535467 width=190) (Current loop: actual time=0.005..58.232 rows=520855, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=14078 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=520854) (Current loop: actual time=0.004..0.004 rows=1, loop number=520855)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=2087084 read=6
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Nested Loop (cost=0.43..8236166.16 rows=15535467 width=380) (Current loop: actual time=0.019..2879.993 rows=1280640, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=5166184 read=15 +
| -> Seq Scan on public.sbtest t1 (cost=0.00..575579.67 rows=15535467 width=190) (Current loop: actual time=0.005..131.568 rows=1280640, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=34612 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.001..0.002 rows=1 loops=1280639) (Current loop: actual time=0.001..0.001 rows=1, loop number=1280640)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=5131572 read=15
leader_pid |
观察进度例子4
来一个并行查询
session a
postgres=# set max_parallel_workers_per_gather =4;
SET
postgres=# set force_parallel_mode =on;
SET
postgres=# select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
session b
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Nested Loop (cost=0.43..8236166.16 rows=15535467 width=380) (Current loop: actual time=0.019..1297.191 rows=520855, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=2101162 read=6 +
| -> Seq Scan on public.sbtest t1 (cost=0.00..575579.67 rows=15535467 width=190) (Current loop: actual time=0.005..58.232 rows=520855, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=14078 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=520854) (Current loop: actual time=0.004..0.004 rows=1, loop number=520855)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=2087084 read=6
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Nested Loop (cost=0.43..8236166.16 rows=15535467 width=380) (Current loop: actual time=0.019..2879.993 rows=1280640, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=5166184 read=15 +
| -> Seq Scan on public.sbtest t1 (cost=0.00..575579.67 rows=15535467 width=190) (Current loop: actual time=0.005..131.568 rows=1280640, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=34612 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.001..0.002 rows=1 loops=1280639) (Current loop: actual time=0.001..0.001 rows=1, loop number=1280640)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=5131572 read=15
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+----------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Nested Loop (cost=0.43..8236166.16 rows=15535467 width=380) (Current loop: actual time=0.019..4281.219 rows=1948809, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=7861798 read=24 +
| -> Seq Scan on public.sbtest t1 (cost=0.00..575579.67 rows=15535467 width=190) (Current loop: actual time=0.005..196.114 rows=1948810, loop number=1)+
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=52671 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.001..0.002 rows=1 loops=1948809) +
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=7809127 read=24
leader_pid |
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Gather (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.247..422.093 rows=1214899, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Workers Planned: 4 +
| Workers Launched: 4 +
| Buffers: shared hit=5074 +
| -> Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.016..2.697 rows=1258, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=5074 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.003..0.132 rows=1258, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=34 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.001..0.002 rows=1 loops=1257) (Current loop: actual time=0.002..0.002 rows=1, loop number=1258)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=5040
leader_pid |
-[ RECORD 2 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37973
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..734.275 rows=316572, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=1277149 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.004..32.660 rows=316573, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=8557 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=316572) +
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=1268593
leader_pid | 36918
-[ RECORD 3 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37972
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..726.460 rows=307861, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=1241821 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.004..32.622 rows=307861, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=8321 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=307860) (Current loop: actual time=0.002..0.002 rows=1, loop number=307861) +
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=1233500
leader_pid | 36918
-[ RECORD 4 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37971
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..719.893 rows=311324, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=1255903 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.005..32.527 rows=311324, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=8415 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=311323) (Current loop: actual time=0.001..0.001 rows=1, loop number=311324) +
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=1247488
leader_pid | 36918
-[ RECORD 5 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37970
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.024..748.139 rows=278393, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=1123109 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.007..32.654 rows=278393, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=7525 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=278392) (Current loop: actual time=0.004..0.004 rows=1, loop number=278393) +
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=1115584
leader_pid | 36918
postgres=# select * from pg_query_state(36918,true,true,true,true,true);
-[ RECORD 1 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 36918
frame_number | 0
query_text | select * from sbtest t1 join sbtest t2 on (t1.id=t2.id);
plan | Gather (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.247..1465.785 rows=4177376, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Workers Planned: 4 +
| Workers Launched: 4 +
| Buffers: shared hit=5074 +
| -> Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.016..2.697 rows=1258, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=5074 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.003..0.132 rows=1258, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=34 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.001..0.002 rows=1 loops=1257) (Current loop: actual time=0.002..0.002 rows=1, loop number=1258)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=5040
leader_pid |
-[ RECORD 2 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37973
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..2558.920 rows=1065636, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=4299076 read=3 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.004..110.952 rows=1065636, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=28801 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=1065635) (Current loop: actual time=0.002..0.002 rows=1, loop number=1065636)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=4270207 read=3
leader_pid | 36918
-[ RECORD 3 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37972
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..2539.481 rows=1041373, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=4200840 read=2 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.004..111.095 rows=1041373, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=28149 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=1041372) (Current loop: actual time=0.003..0.003 rows=1, loop number=1041373)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=4172691 read=2
leader_pid | 36918
-[ RECORD 4 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37971
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.015..2489.942 rows=1035703, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=4178122 read=1 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.005..108.320 rows=1035703, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=27993 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=1035702) (Current loop: actual time=0.003..0.003 rows=1, loop number=1035703)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=4150129 read=1
leader_pid | 36918
-[ RECORD 5 ]+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid | 37970
frame_number | 0
query_text | <parallel query>
plan | Nested Loop (cost=0.43..2374210.41 rows=15535467 width=380) (Current loop: actual time=0.024..2562.090 rows=1033870, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad, t2.id, t2.k, t2.c, t2.pad +
| Buffers: shared hit=4170779 read=1 +
| -> Parallel Seq Scan on public.sbtest t1 (cost=0.00..459063.67 rows=3883867 width=190) (Current loop: actual time=0.007..110.571 rows=1033870, loop number=1) +
| Output: t1.id, t1.k, t1.c, t1.pad +
| Buffers: shared hit=27946 +
| -> Index Scan using pk_sbtest_id on public.sbtest t2 (cost=0.43..0.48 rows=1 width=190) (actual time=0.002..0.002 rows=1 loops=1033869) (Current loop: actual time=0.003..0.003 rows=1, loop number=1033870)+
| Output: t2.id, t2.k, t2.c, t2.pad +
| Index Cond: (t2.id = t1.id) +
| Buffers: shared hit=4142833 read=1
leader_pid | 36918
手册
pg_query_state
The pg_query_state module provides facility to know the current state of query execution on working backend. To enable this extension you have to patch the latest stable version of PostgreSQL. Different branches are intended for different version numbers of PostgreSQL, e.g., branch PG9_5 corresponds to PostgreSQL 9.5.
Overview
Each complex query statement (SELECT/INSERT/UPDATE/DELETE) after optimization/planning stage is translated into plan tree wich is kind of imperative representation of declarative SQL query. EXPLAIN ANALYZE request allows to demonstrate execution statistics gathered from each node of plan tree (full time of execution, number rows emitted to upper nodes, etc). But this statistics is collected after execution of query. This module allows to show actual statistics of query running on external backend. At that, format of resulting output is almost identical to ordinal EXPLAIN ANALYZE. Thus users are able to track of query execution in progress.
In fact, this module is able to explore external backend and determine its actual state. Particularly it’s helpful when backend executes a heavy query or gets stuck.
Use cases
Using this module there can help in the following things:
- detect a long query (along with other monitoring tools)
- overwatch the query execution (example)
Installation
To install pg_query_state, please apply patches custom_signal.patch, executor_hooks.patch and runtime_explain.patch to the latest stable version of PostgreSQL and rebuild PostgreSQL.
Correspondence branch names to PostgreSQL version numbers:
- PG9_5 — PostgreSQL 9.5
- PGPRO9_5 — PostgresPro 9.5
- master — development version for PostgreSQL 10devel
Then execute this in the module’s directory:
make install USE_PGXS=1
Add module name to the shared_preload_libraries parameter in postgresql.conf:
shared_preload_libraries = 'pg_query_state'
It is essential to restart the PostgreSQL instance. After that, execute the following query in psql:
CREATE EXTENSION pg_query_state;
Done!
Tests
Tests using parallel sessions using python 2.7 script:
python tests/pg_qs_test_runner.py [OPTION]...
prerequisite packages:
psycopg2version 2.6 or laterPyYAMLversion 3.11 or later
options:
- - -host — postgres server host, default value is localhost
- - -port — postgres server port, default value is 5432
- - -database — database name, default value is postgres
- - -user — user name, default value is postgres
- - -password — user’s password, default value is empty
Function pg_query_state
pg_query_state(integer pid,
verbose boolean DEFAULT FALSE,
costs boolean DEFAULT FALSE,
timing boolean DEFAULT FALSE,
buffers boolean DEFAULT FALSE,
triggers boolean DEFAULT FALSE,
format text DEFAULT 'text')
Extract current query state from backend with specified pid. Since parallel query can spawn workers and function call causes nested subqueries so that state of execution may be viewed as stack of running queries, return value of pg_query_state has type TABLE (pid integer, frame_number integer, query_text text, plan text, leader_pid integer). It represents tree structure consisting of leader process and its spawned workers. Each worker refers to leader through leader_pid column. For leader process the value of this column is null. For each process the stack frames are specified as correspondence between frame_number, query_text and plan columns.
Thus, user can see the states of main query and queries generated from function calls for leader process and all workers spawned from it.
In process of execution some nodes of plan tree can take loops of full execution. Therefore statistics for each node consists of two parts: average statistics for previous loops just like in EXPLAIN ANALYZE output and statistics for current loop if node have not finished.
Optional arguments:
verbose— use EXPLAIN VERBOSE for plan printing;costs— add costs for each node;timing— print timing data for each node, if collecting of timing statistics is turned off on called side resulting output will contain WARNING messagetiming statistics disabled;buffers— print buffers usage, if collecting of buffers statistics is turned off on called side resulting output will contain WARNING messagebuffers statistics disabled;triggers— include triggers statistics in result plan trees;format— EXPLAIN format to be used for plans printing, posible values: {text,xml,json,yaml}.
If callable backend is not executing any query the function prints INFO message about backend’s state taken from pg_stat_activity view if it exists there.
Calling role have to be superuser or member of the role whose backend is being called. Othrewise function prints ERROR message permission denied.
Configuration settings
There are several user-accessible GUC variables designed to toggle the whole module and the collecting of specific statistic parameters while query is running:
pg_query_state.enable— disable (or enable)pg_query_statecompletely, default value istruepg_query_state.enable_timing— collect timing data for each node, default value isfalsepg_query_state.enable_buffers— collect buffers usage, default value isfalse
This parameters is set on called side before running any queries whose states are attempted to extract. Warning: if pg_query_state.enable_timing is turned off the calling side cannot get time statistics, similarly for pg_query_state.enable_buffers parameter.
Examples
Assume one backend with pid = 20102 performs a simple query:
postgres=# select pg_backend_pid();
pg_backend_pid
----------------
20102
(1 row)
postgres=# select count(*) from foo join bar on foo.c1=bar.c1;
Other backend can extract intermediate state of execution that query:
postgres=# \x
postgres=# select * from pg_query_state(20102);
-[ RECORD 1 ]-----------------------------------------------------------------------------------
query_text | select count(*) from foo join bar on foo.c1=bar.c1;
plan | Aggregate (Current loop: actual rows=0, loop number=1) +
| -> Nested Loop (Current loop: actual rows=6, loop number=1) +
| Join Filter: (foo.c1 = bar.c1) +
| Rows Removed by Join Filter: 0 +
| -> Seq Scan on bar (Current loop: actual rows=6, loop number=1) +
| -> Materialize (actual rows=1000001 loops=5) (Current loop: actual rows=742878, loop number=6)+
| -> Seq Scan on foo (Current loop: actual rows=1000001, loop number=1)
In example above Materialize node has statistics on passed loops (average number of rows delivered to Nested Loop and number of passed loops are shown) and statistics on current loop. Other nodes has statistics only for current loop as this loop is first (loop number = 1).
Assume first backend executes some function:
postgres=# select n_join_foo_bar();
Other backend can get the follow output:
postgres=# select * from pg_query_state(20102);
-[ RECORD 1 ]---------------------------------------------------------------------------------------------------------------
query_text | select n_join_foo_bar();
plan | Result (Current loop: actual rows=0, loop number=1)
-[ RECORD 2 ]---------------------------------------------------------------------------------------------------------------
query_text | SELECT (select count(*) from foo join bar on foo.c1=bar.c1)
plan | Result (Current loop: actual rows=0, loop number=1) +
| InitPlan 1 (returns $0) +
| -> Aggregate (Current loop: actual rows=0, loop number=1) +
| -> Nested Loop (Current loop: actual rows=8, loop number=1) +
| Join Filter: (foo.c1 = bar.c1) +
| Rows Removed by Join Filter: 0 +
| -> Seq Scan on bar (Current loop: actual rows=9, loop number=1) +
| -> Materialize (actual rows=1000001 loops=8) (Current loop: actual rows=665090, loop number=9)+
| -> Seq Scan on foo (Current loop: actual rows=1000001, loop number=1)
First row corresponds to function call, second - to query which is in the body of that function.
We can get result plans in different format (e.g. json):
postgres=# select * from pg_query_state(pid := 20102, format := 'json');
-[ RECORD 1 ]-----------------------------------------------------------
query_text | select n_join_foo_bar();
plan | { +
| "Plan": { +
| "Node Type": "Result", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 0 +
| } +
| } +
| }
-[ RECORD 2 ]-----------------------------------------------------------
query_text | SELECT (select count(*) from foo join bar on foo.c1=bar.c1)
plan | { +
| "Plan": { +
| "Node Type": "Result", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 0 +
| }, +
| "Plans": [ +
| { +
| "Node Type": "Aggregate", +
| "Strategy": "Plain", +
| "Parent Relationship": "InitPlan", +
| "Subplan Name": "InitPlan 1 (returns $0)", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 0 +
| }, +
| "Plans": [ +
| { +
| "Node Type": "Hash Join", +
| "Parent Relationship": "Outer", +
| "Join Type": "Inner", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 124911 +
| }, +
| "Hash Cond": "(foo.c1 = bar.c1)", +
| "Plans": [ +
| { +
| "Node Type": "Seq Scan", +
| "Parent Relationship": "Outer", +
| "Relation Name": "foo", +
| "Alias": "foo", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 1000004 +
| } +
| }, +
| { +
| "Node Type": "Hash", +
| "Parent Relationship": "Inner", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 500000 +
| }, +
| "Hash Buckets": 131072, +
| "Original Hash Buckets": 131072, +
| "Hash Batches": 8, +
| "Original Hash Batches": 8, +
| "Peak Memory Usage": 3221, +
| "Plans": [ +
| { +
| "Node Type": "Seq Scan", +
| "Parent Relationship": "Outer", +
| "Relation Name": "bar", +
| "Alias": "bar", +
| "Current loop": { +
| "Actual Loop Number": 1, +
| "Actual Rows": 500000 +
| } +
| } +
| ] +
| } +
| ] +
| } +
| ] +
| } +
| ] +
| } +
| }
Functions for tracing query execution
For the purpose to achieve a slightly deterministic result from pg_query_state function under regression tests this module introduces specific functions for query tracing running on external backend process. In this case query is suspended after any node has worked off one step in pipeline structure of plan tree execution. Thus we can execute query specific number of steps and get its state which will be deterministic at least on number of emitted rows of each node.
Function executor_step which takes pid of traceable backend provides facility to perform single step of query execution. Function executor_continue which also takes pid completes query without trace interrupts.
Trace mode is set through GUC parameter pg_query_state.executor_trace which default is off. Warning: after setting this parameter any following queries (even specified implicitly, e.g., autocompletion of input in psql) will be interrupted and to resume their executor_continue must be accomplished on external backend. Only after that user can turn off trace mode.
Examples with trace mode
Assume one backend with pid = 20102 sets trace mode and executes a simple query:
postgres=# set pg_query_state.executor_trace to on;
SET
postgres=# select count(*) from foo join bar on foo.c1=bar.c1;
This query is suspended. Then other backend can extract its state:
postgres=# select * from pg_query_state(pid := 20102);
-[ RECORD 1 ]------------------------------------------------------------------------------
query_text | select count(*) from foo join bar on foo.c1=bar.c1;
plan | Aggregate (Current loop: actual rows=0, loop number=1) +
| -> Hash Join (Current loop: actual rows=0, loop number=1) +
| Hash Cond: (foo.c1 = bar.c1) +
| -> Seq Scan on foo (Current loop: actual rows=0, loop number=1) +
| -> Hash (Current loop: actual rows=0, loop number=1) +
| -> Seq Scan on bar (Current loop: actual rows=0, loop number=1)
As you can see none of nodes is executed. We can make one step of execution and see renewed state of query:
postgres=# select executor_step(20102);
-[ RECORD 1 ]-+-
executor_step |
postgres=# select * from pg_query_state(pid := 20102);
-[ RECORD 1 ]------------------------------------------------------------------------------
query_text | select count(*) from foo join bar on foo.c1=bar.c1;
plan | Aggregate (Current loop: actual rows=0, loop number=1) +
| -> Hash Join (Current loop: actual rows=0, loop number=1) +
| Hash Cond: (foo.c1 = bar.c1) +
| -> Seq Scan on foo (Current loop: actual rows=1, loop number=1) +
| -> Hash (Current loop: actual rows=0, loop number=1) +
| -> Seq Scan on bar (Current loop: actual rows=0, loop number=1)
Node Seq Scan on foo has emitted first row to Hash Join. Completion of traceable query is performed as follows:
postgres=# select executor_continue(pid := 20102);
-[ RECORD 1 ]-----+-
executor_continue |
At the same time first backend prints result of query execution:
postgres=# select count(*) from foo join bar on foo.c1=bar.c1;
-[ RECORD 1 ]-
count | 500000
Feedback
Do not hesitate to post your issues, questions and new ideas at the issues page.
Authors
Maksim Milyutin m.milyutin@postgrespro.ru Postgres Professional Ltd., Russia