官人要杯咖啡吗? - PostgreSQL实时监测PLAN tree的执行进度-阿里云开发者社区

开发者社区> 德哥> 正文

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

简介: 标签 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

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

相关文章
C#.NET使用Task,await,async,异步执行控件耗时事件(event),不阻塞UI线程和不跨线程执行UI更新,以及其他方式比较
原文:C#.NET使用Task,await,async,异步执行控件耗时事件(event),不阻塞UI线程和不跨线程执行UI更新,以及其他方式比较 使用Task,await,async,异步执行事件(event),不阻塞UI线程和不跨线程执行UI更新   使用Task,await,async 的异步模式 去执行事件(event) 解决不阻塞UI线程和不夸跨线程执行UI更新报错的最佳实践,附加几种其他方式比较 由于是Winform代码和其他原因,本文章只做代码截图演示,不做界面UI展示,当然所有代码都会在截图展示。
3152 0
惊天性能!单实例RDS PostgreSQL 支撑 2000亿 实时标签透视案例
标签 PostgreSQL , varbitx , 标签 , 任意圈选 , 阿里云 , RDS , bitmap , 分段 , 并行计算 , 异步调用 , dblink , 异步dblink , 游标 背景 20亿用户,每个用户1000个标签,基于任意标签组合圈选、透视(业务上的需求是一次最多计算100个标签的组合)。
3046 0
通过EMR Spark Streaming实时读取Tablestore数据
本文将介绍如何在E-MapReduce中实时流式的处理Tablestore中的数据。 场景设计 随着互联网的发展,企业中积累的数据越来越多,数据的背后隐藏着巨大的价值,在双十一这样的节日中,电子商务企业都会在大屏幕上实时显示订单总量,由于订单总量巨大,不可能每隔一秒就到数据库中进行一次SQL统计,此时就需要用到流计算,而传统的方法都是需要借助Kafka消息队列来做流式计算,数据订单需要写入数据库与Kafka中,Spark Streaming 消费来自Kafka中的订单信息。
3039 0
用PostgreSQL 做实时高效 搜索引擎 - 全文检索、模糊查询、正则查询、相似查询、ADHOC查询
用PostgreSQL 做实时高效 搜索引擎 - 全文检索、模糊查询、正则查询、相似查询、ADHOC查询作者digoal 日期2017-12-05 标签PostgreSQL , 搜索引擎 , GIN , ranking , high light , 全文检索 , 模糊查询 , 正则查询 , 相似查询 , ADHOC查询 背景字符串搜索是非常常见的业务需求,它包括: 1、前缀+模糊查询。
5264 0
AngularJs中,如何在render完成之后,执行Js脚本
AngularJs是Google开源的前端JS框架。使用AngularJs, 我们能够容易地、健壮的开发出类似于Gmail一样的单页Web应用。AngularJs这个新兴的MVC前端框架,具有以下特点: MVC, 模块化,自动化双向数据绑定,语义化标签、依赖注入等。
721 0
+关注
德哥
公益是一辈子的事, I&#39;m digoal, just do it.
2153
文章
245
问答
文章排行榜
最热
最新
相关电子书
更多
文娱运维技术
立即下载
《SaaS模式云原生数据仓库应用场景实践》
立即下载
《看见新力量:二》电子书
立即下载