官人要杯咖啡吗? - PostgreSQL实时监测PLAN tree的执行进度

本文涉及的产品
云原生数据库 PolarDB MySQL 版,通用型 2核4GB 50GB
云原生数据库 PolarDB PostgreSQL 版,标准版 2核4GB 50GB
简介: 标签 PostgreSQL , long query , plan tree , SQL进度条 背景 当我们在数据库中执行一些比较大的查询,或者执行比较复杂的函数时,如果要知道执行到哪里了,预计还要多久。 怎么办呢? 有方法得到吗?当然有。 目前PostgreSQL支持的是传统的SQL执行方法,将(nonutility)语句parser后,根据parser tree生成plan tr

标签

PostgreSQL , long query , plan tree , SQL进度条


背景

当我们在数据库中执行一些比较大的查询,或者执行比较复杂的函数时,如果要知道执行到哪里了,预计还要多久。

怎么办呢? 有方法得到吗?当然有。

目前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的执行进度。

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:

  • psycopg2 version 2.6 or later
  • PyYAML version 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 isnull. 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 message timing statistics disabled;
  • buffers --- print buffers usage, if collecting of buffers statistics is turned off on called side resulting output will contain WARNING message buffers 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_state completely, default value is true
  • pg_query_state.enable_timing --- collect timing data for each node, default value is false
  • pg_query_state.enable_buffers --- collect buffers usage, default value is false

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 t

相关实践学习
使用PolarDB和ECS搭建门户网站
本场景主要介绍基于PolarDB和ECS实现搭建门户网站。
阿里云数据库产品家族及特性
阿里云智能数据库产品团队一直致力于不断健全产品体系,提升产品性能,打磨产品功能,从而帮助客户实现更加极致的弹性能力、具备更强的扩展能力、并利用云设施进一步降低企业成本。以云原生+分布式为核心技术抓手,打造以自研的在线事务型(OLTP)数据库Polar DB和在线分析型(OLAP)数据库Analytic DB为代表的新一代企业级云原生数据库产品体系, 结合NoSQL数据库、数据库生态工具、云原生智能化数据库管控平台,为阿里巴巴经济体以及各个行业的企业客户和开发者提供从公共云到混合云再到私有云的完整解决方案,提供基于云基础设施进行数据从处理、到存储、再到计算与分析的一体化解决方案。本节课带你了解阿里云数据库产品家族及特性。
目录
相关文章
|
搜索推荐 关系型数据库 数据库
《阿里云RDS PostgreSQL实践课 2 实时用户画像数据库实践》电子版地址
阿里云RDS PostgreSQL实践课 2 实时用户画像数据库实践
134 0
《阿里云RDS PostgreSQL实践课 2 实时用户画像数据库实践》电子版地址
|
监控 关系型数据库 PostgreSQL
PostgreSQL 12: 新增 pg_stat_progress_create_index 视图监控索引创建进度
PostgreSQL 12 版本之前,对PostgreSQL大表创建索引时是一个比较痛苦的过程,创建索引过程中无法得知索引创建进度,PostgreSQL 12 在运维监控功能方面得到增强,新增 pg_stat_progress_create_index 视图可以监控索引的创建进度,本文简单演示。
2242 0
|
存储 消息中间件 监控
分布式 PostgreSQL 集群(Citus)官方示例 - 实时仪表盘
分布式 PostgreSQL 集群(Citus)官方示例 - 实时仪表盘
228 0
分布式 PostgreSQL 集群(Citus)官方示例 - 实时仪表盘
|
SQL 关系型数据库 OLAP
【实操系列】AnalyticDB PostgreSQL 万倍查询加速——使用实时物化视图加速带可变参数的查询
以TPCH Q1为例,介绍一个优化案例,使用AnalyticDB PostgreSQL的实时物化视图+自动查询改写,近万倍优化带可变参数的OLAP查询
687 1
【实操系列】AnalyticDB PostgreSQL 万倍查询加速——使用实时物化视图加速带可变参数的查询
|
SQL 关系型数据库 OLAP
AnalyticDB PostgreSQL 万倍查询加速——使用实时物化视图加速带可变参数的查询
以TPCH Q1为例,介绍一个优化案例,使用AnalyticDB PostgreSQL的实时物化视图+自动查询改写,近万倍优化带可变参数的OLAP查询
538 0
|
存储 SQL 搜索推荐
阿里云PostgreSQL案例精选1 - 实时精准营销、人群圈选
标签 PostgreSQL , 阿里云 , 实时精准营销 , 人群圈选 , 广告 背景 行业: 几乎所有行业, 如互联网、新零售、教育、游戏等. 应用场景: 根据目标群体的特征, 快速提取目标群体.例如, 在电商行业中, 商家在搞运营活动前, 根据活动的目标群体的特征, 圈选出一批目标用户进行广告推送或活动条件的命中. 在游戏行业中, 运营经常会根据游戏玩家的某些特征圈
1073 0
|
SQL 弹性计算 关系型数据库
PostgreSQL 大宽表,全列索引,高并发合并写入(insert into on conflict, upsert, merge insert) - 实时adhoc query
标签 PostgreSQL , 全列索引 , 大宽表 , 写测试 , insert on conflict , upsert , merge insert , adhoc query 背景 OLAP系统中,adhoc query非常场景(任意维度查询分析)。 adhoc query,通常来说,可以加GIN倒排,或者每一列都加一个索引来实现。 《PostgreSQL 设计优化case
8627 0
|
存储 SQL 搜索推荐
阿里云PostgreSQL精选案例 - 实时精准营销、人群圈选
标签 PostgreSQL , 阿里云 , 实时精准营销 , 人群圈选 , 广告 背景 行业: 几乎所有行业, 如互联网、新零售、教育、游戏等. 应用场景: 根据目标群体的特征, 快速提取目标群体.
2813 0
阿里云PostgreSQL精选案例 - 实时精准营销、人群圈选
|
消息中间件 存储 JSON
通过流处理平台Kafka与云原生数据仓库PostgreSQL做实时数据交互
本文介绍如何基于流处理平台Kafka与云原生数据仓库AnalyticDB PostgreSQL做实时数据交互
5138 0
通过流处理平台Kafka与云原生数据仓库PostgreSQL做实时数据交互
|
消息中间件 关系型数据库 OLAP
如何基于Flink将流式数据实时写入AnalyticDB for PostgreSQL
本文主要介绍如何通过 Flink 将流式数据实时写入 ADB PG中,并给出代码demo。 本文的Flink 为社区1.7.2版本,ADB PG为阿里云AnalyticDB for PostgreSQL 6.0版。
4477 0
如何基于Flink将流式数据实时写入AnalyticDB for PostgreSQL