1前言

昨天有位朋友问了这样一个问题：

一个存储过程，跑了好几个小时，怎么才能知道跑到哪一步了？

诚然，这个场景的确算是一个痒点——大几百行的函数吭哧吭哧运行着也不知道个进度，完全是一个黑盒。那有没有什么优雅的方式可以知晓存储过程的大概进度？Sure！

2pg_show_plans

我首先想到的便是 pg_show_plans，这个插件我印象深刻，因为曾经给这个插件反馈了一个 BUG 。pg_show_plans 原本是用于展示运行中 SQL 的执行计划，因此你可能会碰到某些 SQL 跑了几天几夜跑不出来，而 auto_explain 这类插件必须要运行完才会记录在日志中。

另外，pg_show_plans 支持显式层级：

level：query nest level. Top level is 0. For example, if you execute a simple select query, the level of this query's plan is 0. If you execute a function that invokes a select query, level 0 is the plan of the function and level 1 is the plan of the select query invoked by the function.

因此 pg_show_plans 也可以用来观测函数。让我们小试牛刀一下：

postgres=# CREATE OR REPLACE FUNCTION public.myfunc ()
    RETURNS integer
    LANGUAGE plpgsql
    AS $function$
DECLARE
    ret int;
BEGIN
    PERFORM pg_sleep(10);
    PERFORM pg_sleep(15);
    SELECT pg_sleep(20), id INTO ret FROM test WHERE id = 99;
    RETURN ret;
END;
$function$;
CREATE FUNCTION

postgres=# create table test(id int);
CREATE TABLE
postgres=# insert into test values(generate_series(1,100000));
INSERT 0 100000
postgres=# select pg_backend_pid();
 pg_backend_pid 
----------------
           6199
(1 row)

postgres=# select * from myfunc();
---运行中

新开一个窗口查看进度

 postgres=# select * from pg_show_plans where pid = 6199;\watch 1
             Thu 03 Aug 2023 03:41:36 PM CST (every 1s)

 pid  | level | userid | dbid  |                           plan                            
------+-------+--------+-------+-----------------------------------------------------------
 6199 |     0 |     10 | 24927 | Function Scan on myfunc  (cost=0.25..0.26 rows=1 width=4)
 6199 |     1 |     10 | 24927 | Result  (cost=0.00..0.01 rows=1 width=4)
(2 rows)

                        Thu 03 Aug 2023 03:41:37 PM CST (every 1s)

 pid  | level | userid | dbid  |                           plan                            
------+-------+--------+-------+-----------------------------------------------------------
 6199 |     0 |     10 | 24927 | Function Scan on myfunc  (cost=0.25..0.26 rows=1 width=4)
 6199 |     1 |     10 | 24927 | Seq Scan on test  (cost=0.00..1693.00 rows=1 width=8)    +
      |       |        |       |   Filter: (id = 99)
(2 rows)
...

可以看到当前正在顺序扫描 test，通过执行计划可以知晓函数大致运行进度 ??

3pg_query_state

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 stable version of PostgreSQL, recompile it and deploy new binaries. All patch files are located in patches/ directory and tagged with suffix of PostgreSQL version number.

但是使用这个插件需要打 patch，原生 PostgreSQL 是不能用的。这里就不做演示了，各位参照 https://github.com/postgrespro/pg_query_state，里面也有相关 patch。

postgres=# select * from pg_query_state(49265);
-[ RECORD 1 ]+------------------------------------------------------------------------------------------------------------------
pid          | 49265
frame_number | 0
query_text   | select n_join_foo_bar();
plan         | Result (Current loop: actual rows=0, loop number=1)
leader_pid   | (null)
-[ RECORD 2 ]+------------------------------------------------------------------------------------------------------------------
pid          | 49265
frame_number | 1
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=51, loop number=1)                                          +
             |                 Join Filter: (foo.c1 = bar.c1)                                                                   +
             |                 Rows Removed by Join Filter: 51636304                                                            +
             |                 ->  Seq Scan on bar (Current loop: actual rows=52, loop number=1)                                +
             |                 ->  Materialize (actual rows=1000000 loops=51) (Current loop: actual rows=636355, loop number=52)+
             |                       ->  Seq Scan on foo (Current loop: actual rows=1000000, loop number=1)
leader_pid   | (null)

4pg_progress

还有一个较老的插件是 pg_progress，但是年代久远，尝试编译了报错就没有继续。

A PostgreSQL extension to estimate query progress. Based on ideas from a research paper "Estimating progress of SQL queries" by Surajit Chaudhuri and Vivek Narasayya from Microsoft Research and Ravi Ramamurthy from the University of Wisconsin.

5土办法

前面几种是通过插件的形式，稍微高大上一点。土办法当然也有——万能的 raise notice

CREATE OR REPLACE FUNCTION public.myfunc ()
    RETURNS integer
    LANGUAGE plpgsql
    AS $function$
DECLARE
    ret int;
BEGIN
 raise notice 'first sleep';
    PERFORM pg_sleep(10);
    raise notice 'second sleep';
    PERFORM pg_sleep(15);
    raise notice 'scan table test';
    SELECT pg_sleep(20), id INTO ret FROM test WHERE id = 99;
    RETURN ret;
END;
$function$;
CREATE FUNCTION
postgres=# select * from myfunc();
NOTICE:  first sleep
NOTICE:  second sleep
NOTICE:  scan table test
...

类似的，你可以创建一个序列

CREATE SEQUENCE query_progress START 1;

然后在函数里面调用序列

AND NEXTVAL('query_progress')!=0

举个例子

CREATE OR REPLACE FUNCTION public.myfunc ()
    RETURNS int
    LANGUAGE plpgsql
    AS $function$
DECLARE
 ret int;
BEGIN
  --raise notice 'first sleep';
    perform NEXTVAL('query_progress')!=0;
    PERFORM pg_sleep(10);
    --raise notice 'second sleep';
    perform NEXTVAL('query_progress')!=0;
    PERFORM pg_sleep(15);
    raise notice 'scan table test';
    SELECT pg_sleep(20), id INTO ret FROM test WHERE id = 99 and NEXTVAL('query_progress')!=0;
    RETURN ret;
END;
$function$;

Thu 03 Aug 2023 04:26:25 PM CST (every 1s)

 last_value | log_cnt | is_called 
------------+---------+-----------
          2 |      31 | t
(1 row)

Thu 03 Aug 2023 04:26:26 PM CST (every 1s)

 last_value | log_cnt | is_called 
------------+---------+-----------
          3 |      30 | t
(1 row)

Thu 03 Aug 2023 04:26:27 PM CST (every 1s)

 last_value | log_cnt | is_called 
------------+---------+-----------
          3 |      30 | t
(1 row)

通过 last_value 你便可以知晓当前运行步骤了。当然这种方式有一定的侵入性，并且不适用于所有查询。

6调试函数性能

以上是追踪函数进度，还有一个常见的场景是调试函数，内部的任何问题都有可能造成性能瓶颈。通常会遇到以下情况：

出现问题的语句，其实执行地非常快，但是调用过次数多导致变慢
随机出现的性能瓶颈问题
生产系统上出现了性能问题（尽管我们不愿意直接上生产系统排查）

首先是 auto_explain，用于向日志输出超出定义阈值执行时间的SQL的执行计划，并且可以选择是否输出内嵌SQL的执行计划（如函数中的SQL）。

auto_explain.log_nested_statements causes nested statements (statements executed inside a function) to be considered for logging. When it is off, only top-level query plans are logged. This parameter is off by default. Only superusers can change this setting.

同理，pg_stat_statements也可以，

pg_stat_statements.track controls which statements are counted by the module. Specify top to track top-level statements (those issued directly by clients), all to also track nested statements (such as statements invoked within functions), or none to disable statement statistics collection. The default value is top. Only superusers can change this setting.

插件：pldbgapi、pldebugger + pgAdmin、plprofiler，pldebugger 需要配合 pgAdmin 一起调试（打断点，一步一步调试），而 plprofiler 会生成一个类似火焰图的形式（需要搭配 python，离线安装极其痛苦），更加直观，具体原理可以参照阿里内核月报 PgSQL · 插件分析 · plProfiler

7小结

以上便是调试函数、分析函数的常见手段了。顺带打个小广告? 实战精英课，感兴趣的老铁可以滴滴我。

8参考

https://www.endpointdev.com/blog/2010/04/viewing-postgres-function-progress-from/

http://mysql.taobao.org/monthly/2020/03/10/

https://postgres.ai/blog/20220114-progress-bar-for-postgres-queries-lets-dive-deeper

如何调试分析函数

1前言

2pg_show_plans

3pg_query_state

4pg_progress

5土办法

6调试函数性能

7小结

8参考