PostgreSQL学徒

pg_stat_statements的有趣案例

前言

今天一位同事找到我说:"灿哥,我有个库每隔一阵CPU就冲高",现象如下👇🏻

Image

可以看到,CPU每隔15分钟就会冲高一下,这位与PostgreSQL八字不合的同事经常能遇到一些奇奇怪怪的问题或BUG,让我们一起分析一下这个有趣的生产案例!

分析

第一时间能想到的当然是慢查询了,在这个库中log_min_duration_statement配置的是1秒,意味着执行时间超过1s的SQL都会记录在日志中,但是通过分析,在问题时间段的日志中并没有记录业务相关的慢查询,都是一堆连接认证的日志。唯一蛛丝马迹是,在日志中有我们的AWR语句,每条SQL执行时间都在4s左右,duration:4392.781 ms。那么是否是AWR导致的?在我们内部,AWR是基于pg_stat_statements实现的,目前原生PostgreSQL的一大痛点就是不支持ASH/AWR,一旦碰到故障,秋后算账就比较恼火,现场都没了也只能干瞪眼。因此常见的方案之一便是基于pg_stat_statements去实现AWR,毕竟这个视图里面的内容很丰富,这一点TimescaleDB已经提供了一个很好的例子,详见 Identify Slow PostgreSQL Queries with pg_stat_statements。

回到问题上来,查看操作系统的crontab,发现确实每隔15分钟就会去采集一次AWR,和问题出现的频率相吻合,那重点分析一下这个AWR。先在数据库里看一下情况,pg_stat_statements是一个视图,实际调用的是pg_stat_statements()函数。简单模拟查询一下

postgres=# explain analyze select count(*) from pg_stat_statements;
                                                         QUERY PLAN                                                        

  ---------------------------------------------------------------------------------------------------------------------------
--
 Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=4145.352..4145.353 rows=1 loops=1)
   ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=3809.405..4144.071 rows=3199 loops=1
)
 Planning Time: 0.113 ms
 Execution Time: 4411.721 ms
(4 rows)

postgres=# explain analyze select count(*) from pg_stat_statements limit 1;
                                                            QUERY PLAN                                                     

        ---------------------------------------------------------------------------------------------------------------------------
--------
 Limit  (cost=12.50..12.51 rows=1 width=8) (actual time=4139.022..4139.024 rows=1 loops=1)
   ->  Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=4139.021..4139.021 rows=1 loops=1)
         ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=3803.080..4137.715 rows=3199 l
oops=1)
 Planning Time: 0.124 ms
 Execution Time: 4406.723 ms
(5 rows)

postgres=# explain analyze select count(*) from pg_stat_statements(true) limit 1;
                                                            QUERY PLAN                                                     

        ---------------------------------------------------------------------------------------------------------------------------
--------
 Limit  (cost=12.50..12.51 rows=1 width=8) (actual time=4157.667..4157.669 rows=1 loops=1)
   ->  Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=4157.666..4157.667 rows=1 loops=1)
         ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=3821.351..4156.348 rows=3199 l
oops=1)
 Planning Time: 0.063 ms
 Execution Time: 4425.210 ms
(5 rows)

可以看到在这个库中查询pg_stat_statements需要花费4s,总共3199行。而一个"正常"的实例是下面这个样子

postgres=# explain analyze select count(*) from pg_stat_statements;
                                                         QUERY PLAN                                                        

  ---------------------------------------------------------------------------------------------------------------------------
--
 Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=4.842..4.845 rows=1 loops=1)
   ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=4.474..4.720 rows=1783 loops=1
)
 Planning Time: 0.253 ms
 Execution Time: 5.181 ms
(4 rows)

postgres=# explain analyze select count(*) from pg_stat_statements limit 1;
                                                            QUERY PLAN                                                     

        ---------------------------------------------------------------------------------------------------------------------------
--------
 Limit  (cost=12.50..12.51 rows=1 width=8) (actual time=5.164..5.166 rows=1 loops=1)
   ->  Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=5.160..5.160 rows=1 loops=1)
         ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=4.823..5.009 rows=1784 l
oops=1)
 Planning Time: 0.117 ms
 Execution Time: 5.240 ms
(5 rows)

耗时5ms,但是总条数相差并不大,只有1784行,也就差了1200多条,但是执行时间却差了800倍!是什么导致了这样的差异呢?

用strace抓一下调用,在执行的过程中可以看到大量的pwrite64(28, "098,\n "..., 8192, 447553536) = 8192,说明进程在写28号文件描述符所对应的文件,我们可以通过/proc/pid/fd查看文件描述符对应的是哪个文件,当然也可以通过 lsof -p 查看某个进程打开了哪些文件

28 -> /xxx/base/pgsql_tmp/pgsql_tmp82840.8

[root@xiongcc ~]# lsof -p 82840 | grep pgsql_tmp
postgres 82840 postgres  29u       REG       253,339  391036928   67145745 /xxx/base/pgsql_tmp/pgsql_tmp82840.8

可以看到,28号文件描述符对应的是pgsql_tmp目录下的某个文件。

工作原理

气氛都到这了,不妨继续思考一下几个问题:

  1. pg_stat_statements插件如何工作?
  2. 当数据库关闭之后,pg_stat_statements采集的信息会持久化到何处?
  3. 当数据库运行时,统计数据存放在何处?
  4. 什么情况下需要把文件存放到pgsql_tmp目录下?

好在pg_stat_statements的代码不长,pg_stat_statements和众多插件一样,使用hook,俗称钩子,钩子是切入到PostgreSQL的内部运行机制中,对运行过程进行修改和中断的一种机制。用到hook的插件,通常需要在会话建立时,或者在数据库启动时,加载动态库,采用 _PG_init()接口来自动加载hook的定义(load so文件时自动加载),从而让数据库执行某些函数时,跳转到对应HOOK中。

当postmaster进程启动之后,如果发现有shmem_startup_hook的时候,就会去执行hook函数。有很多种类的hook

[postgres@xiongcc contrib]$ grep -r -i hook *| more
Binary file adminpack/adminpack.o matches
Binary file adminpack/adminpack.so matches
Binary file amcheck/verify_heapam.o matches
Binary file amcheck/amcheck.so matches
Binary file amcheck/verify_nbtree.o matches
auth_delay/auth_delay.c:/* Original Hook */
auth_delay/auth_delay.c:static ClientAuthentication_hook_type original_client_auth_hook = NULL;
auth_delay/auth_delay.c:         * Any other plugins which use ClientAuthentication_hook.
auth_delay/auth_delay.c:        if (original_client_auth_hook)
auth_delay/auth_delay.c:                original_client_auth_hook(port, status);
auth_delay/auth_delay.c:        /* Install Hooks */
auth_delay/auth_delay.c:        original_client_auth_hook = ClientAuthentication_hook;
auth_delay/auth_delay.c:        ClientAuthentication_hook = auth_delay_checks;
Binary file auth_delay/auth_delay.o matches
Binary file auth_delay/auth_delay.so matches
auto_explain/auto_explain.c:/* Saved hook values in case of unload */
auto_explain/auto_explain.c:static ExecutorStart_hook_type prev_ExecutorStart = NULL;
auto_explain/auto_explain.c:static ExecutorRun_hook_type prev_ExecutorRun = NULL;
auto_explain/auto_explain.c:static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
auto_explain/auto_explain.c:static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
auto_explain/auto_explain.c:    /* Install hooks. */
auto_explain/auto_explain.c:    prev_ExecutorStart = ExecutorStart_hook;
auto_explain/auto_explain.c:    ExecutorStart_hook = explain_ExecutorStart;
auto_explain/auto_explain.c:    prev_ExecutorRun = ExecutorRun_hook;
auto_explain/auto_explain.c:    ExecutorRun_hook = explain_ExecutorRun;
auto_explain/auto_explain.c:    prev_ExecutorFinish = ExecutorFinish_hook;
auto_explain/auto_explain.c:    ExecutorFinish_hook = explain_ExecutorFinish;
auto_explain/auto_explain.c:    prev_ExecutorEnd = ExecutorEnd_hook;

Image

目前pg_stat_statements定义了这么多hook 👇🏻

 /*
  * Install hooks.
  */

 prev_shmem_request_hook = shmem_request_hook;
 shmem_request_hook = pgss_shmem_request;
 prev_shmem_startup_hook = shmem_startup_hook;
 shmem_startup_hook = pgss_shmem_startup;
 prev_post_parse_analyze_hook = post_parse_analyze_hook;
 post_parse_analyze_hook = pgss_post_parse_analyze;
 prev_planner_hook = planner_hook;
 planner_hook = pgss_planner;
 prev_ExecutorStart = ExecutorStart_hook;   ---
 ExecutorStart_hook = pgss_ExecutorStart;
 prev_ExecutorRun = ExecutorRun_hook;
 ExecutorRun_hook = pgss_ExecutorRun;
 prev_ExecutorFinish = ExecutorFinish_hook;
 ExecutorFinish_hook = pgss_ExecutorFinish;
 prev_ExecutorEnd = ExecutorEnd_hook;
 ExecutorEnd_hook = pgss_ExecutorEnd;
 prev_ProcessUtility = ProcessUtility_hook;
 ProcessUtility_hook = pgss_ProcessUtility;

比如ExecutorStart_hook可以对ExecutorRun()函数进行修改,ExecutorFinish_hook可以对ExecutorFinish()函数进行修改。ExecutorRun就是优化器生成plan tree之后去真正执行SQL的步骤。

Image

/* ----------------------------------------------------------------
 *  ExecutorRun
 *
 *  This is the main routine of the executor module. It accepts
 *  the query descriptor from the traffic cop and executes the
 *  query plan.
 *
 *  ExecutorStart must have been called already.
 *
 *  If direction is NoMovementScanDirection then nothing is done
 *  except to start up/shut down the destination.  Otherwise,
 *  we retrieve up to 'count' tuples in the specified direction.
 *
 *  Note: count = 0 is interpreted as no portal limit, i.e., run to
 *  completion.  Also note that the count limit is only applied to
 *  retrieved tuples, not for instance to those inserted/updated/deleted
 *  by a ModifyTable plan node.
 *
 *  There is no return value, but output tuples (if any) are sent to
 *  the destination receiver specified in the QueryDesc; and the number
 *  of tuples processed at the top level can be found in
 *  estate->es_processed.
 *
 *  We provide a function hook variable that lets loadable plugins
 *  get control when ExecutorRun is called.  Such a plugin would
 *  normally call standard_ExecutorRun().
 *
 * ----------------------------------------------------------------
 */

void
ExecutorRun(QueryDesc *queryDesc,
   ScanDirection direction, uint64 count,
   bool execute_once)

{
 if (ExecutorRun_hook)   //如果有钩子函数,则执行钩子函数
  (*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
 else           //否则执行标准函数
  standard_ExecutorRun(queryDesc, direction, count, execute_once);
}

void
standard_ExecutorRun(QueryDesc *queryDesc,
                     ScanDirection direction, uint64 count, bool execute_once)

{
    EState     *estate;            //执行器状态信息
    CmdType     operation;         //命令类型,这里是INSERT
    DestReceiver *dest;            //目标接收器
    bool        sendTuples;         //是否需要传输Tuples
    MemoryContext oldcontext;       //内存上下文

有了这些HOOK之后,那么就可以很方便地实现采样统计了

Image

当流程执行到pgss_ExecutorEnd的时候,调用pgss_store来存储SQL运行信息到共享内存的哈希表里

/*
 * ExecutorEnd hook: store results if needed
 */

static void
pgss_ExecutorEnd(QueryDesc *queryDesc)
{
 uint64  queryId = queryDesc->plannedstmt->queryId;

 if (queryId != UINT64CONST(0) && queryDesc->totaltime &&
  pgss_enabled(exec_nested_level))
 {
  /*
   * Make sure stats accumulation is done.  (Note: it's okay if several
   * levels of hook all do this.)
   */

  InstrEndLoop(queryDesc->totaltime);

  pgss_store(queryDesc->sourceText,
       queryId,
       queryDesc->plannedstmt->stmt_location,
       queryDesc->plannedstmt->stmt_len,
       PGSS_EXEC,
       queryDesc->totaltime->total * 1000.0, /* convert to msec */
       queryDesc->estate->es_processed,
       &queryDesc->totaltime->bufusage,
       &queryDesc->totaltime->walusage,
       queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL,
       NULL);
 }

 if (prev_ExecutorEnd)
  prev_ExecutorEnd(queryDesc);
 else
  standard_ExecutorEnd(queryDesc);
}

具体哈希表我们可以查询pg_shmem_allocations

postgres=# select * from pg_shmem_allocations where name like '%statement%';
          name           |    off    | size | allocated_size 
-------------------------+-----------+------+----------------
 pg_stat_statements hash | 147468416 | 2896 |           2944
 pg_stat_statements      | 147468288 |   64 |            128
(2 rows)

如何存储

分析完了基本原理,再看一下这些信息是如何存储的?在pg_stat_statements.c中有如下定义

/* Location of permanent stats file (valid when database is shut down) */     ---文件持久化所在位置
#define PGSS_DUMP_FILE PGSTAT_STAT_PERMANENT_DIRECTORY "/pg_stat_statements.stat"

/*
 * Location of external query text file.   ---查询文本所在位置
 */

#define PGSS_TEXT_FILE PG_STAT_TMP_DIR "/pgss_query_texts.stat"

/* ----------
 * Paths for the statistics files (relative to installation's $PGDATA).
 * ----------
 */

#define PGSTAT_STAT_PERMANENT_DIRECTORY  "pg_stat"
#define PGSTAT_STAT_PERMANENT_FILENAME  "pg_stat/pgstat.stat"
#define PGSTAT_STAT_PERMANENT_TMPFILE    "pg_stat/pgstat.tmp"

/* Default directory to store temporary statistics data in */
#define PG_STAT_TMP_DIR  "pg_stat_tmp"

可以看到,当数据库关闭之后,会持久化到pg_stat/pg_stat_statements.stat中

[postgres@xiongcc ~]$ ll pgdata/pg_stat_tmp/
total 124
-rw------- 1 postgres postgres   3890 Aug  3 10:04 db_0.stat
-rw------- 1 postgres postgres   1592 Aug  3 10:04 global.stat
-rw------- 1 postgres postgres 112344 Aug  3 10:04 pgss_query_texts.stat
[postgres@xiongcc ~]$ pg_ctl -D pgdata stop
waiting for server to shut down.... done
server stopped
[postgres@xiongcc ~]$ ll pgdata/pg_stat_tmp/
total 0
[postgres@xiongcc ~]$ ll pgdata/pg_stat
total 300
-rw------- 1 postgres postgres   3890 Aug  3 10:05 db_0.stat
-rw------- 1 postgres postgres  21650 Aug  3 10:05 db_13892.stat
-rw------- 1 postgres postgres   9625 Aug  3 10:05 db_16522.stat
-rw------- 1 postgres postgres   1592 Aug  3 10:05 global.stat
-rw------- 1 postgres postgres 255732 Aug  3 10:05 pg_stat_statements.stat

而当数据库运行时,会将采集到的查询文本临时存储到pg_stat_tmp/pgss_query_texts.stat文件中。

[postgres@xiongcc pg_stat_tmp]$ hexdump -C pgss_query_texts.stat | more
00000000  65 78 70 6c 61 69 6e 20  61 6e 61 6c 79 7a 65 20  |explain analyze |
00000010  73 65 6c 65 63 74 20 63  6f 75 6e 74 28 2a 29 20  |select count(*) |
00000020  66 72 6f 6d 20 74 20 67  72 6f 75 70 20 62 79 20  |from t group by |
00000030  69 64 00 63 72 65 61 74  65 20 64 61 74 61 62 61  |id.create databa|
00000040  73 65 20 72 65 70 6d 67  72 20 6f 77 6e 65 72 20  |se repmgr owner |
00000050  72 65 70 6d 67 72 00 73  65 74 20 73 65 61 72 63  |repmgr.set searc|
00000060  68 5f 70 61 74 68 20 74  6f 20 27 72 65 70 6d 67  |h_path to 'repmg|
00000070  72 27 00 53 45 54 20 73  79 6e 63 68 72 6f 6e 69  |r'
.SET synchroni|
00000080  7a 65 5f 73 65 71 73 63  61 6e 73 20 54 4f 20 6f  |ze_seqscans TO o|
00000090  66 66 00 53 45 4c 45 43  54 20 70 2e 74 61 62 6c  |ff.SELECT p.tabl|
000000a0  65 6f 69 64 2c 20 70 2e  6f 69 64 2c 20 70 2e 70  |eoid, p.oid, p.p|
000000b0  72 6f 6e 61 6d 65 20 41  53 20 61 67 67 6e 61 6d  |roname AS aggnam|
000000c0  65 2c 20 70 2e 70 72 6f  6e 61 6d 65 73 70 61 63  |e, p.pronamespac|
000000d0  65 20 41 53 20 61 67 67  6e 61 6d 65 73 70 61 63  |e AS aggnamespac|
000000e0  65 2c 20 70 2e 70 72 6f  6e 61 72 67 73 2c 20 70  |e, p.pronargs, p|
000000f0  2e 70 72 6f 61 72 67 74  79 70 65 73 2c 20 28 53  |.proargtypes, (S|

postgres=# select query from pg_stat_statements limit 4;
                       query                        
----------------------------------------------------
 explain analyze select count(*) from t group by id
 create database repmgr owner repmgr
 set search_path to 'repmgr'
 SET synchronize_seqscans TO off
(4 rows)

假如挪走pgss_query_texts.stat,就查询不到了

[postgres@xiongcc pg_stat_tmp]$ mv pgss_query_texts.stat pgss_query_texts.stat_bak
[postgres@xiongcc pg_stat_tmp]$ psql -c "select query from pg_stat_statements limit 10"
 query 
-------

          (10 rows)

[postgres@xiongcc pg_stat_tmp]$ mv pgss_query_texts.stat_bak pgss_query_texts.stat
[postgres@xiongcc pg_stat_tmp]$ psql -c "select query from pg_stat_statements limit 1"
                       query                        
----------------------------------------------------
 explain analyze select count(*) from t group by id
(1 row)

这一块在官网上也有说明

“

The representative query texts are kept in an external disk file, and do not consume shared memory. Therefore, even very lengthy query texts can be stored successfully. However, if many long query texts are accumulated, the external file might grow unmanageably large. As a recovery method if that happens, pg_stat_statements may choose to discard the query texts, whereupon all existing entries in the pg_stat_statements view will show null query fields, though the statistics associated with each queryid are preserved. If this happens, consider reducing pg_stat_statements.max to prevent recurrences.

代表性的查询文本保存在外部磁盘文件中,不占用共享内存。因此,即使是非常长的查询文本也可以成功地存储。但是,如果累积了许多长查询文本,外部文件可能会大到无法管理的地步。如果发生这种情况,作为一种恢复方法,pg_stat_statement可以选择丢弃查询文本,因此pg_stat_statement 视图中的所有现有条目将显示空查询字段,但是与每个查询字段相关联的统计信息将保留。如果发生这种情况,请考虑减少pg_stat_statements.max值防止复发。

查询会丢弃,单独存储在外部文件中而不占用共享存储,但是其他字段会被保留。

[postgres@xiongcc pg_stat_tmp]$ mv pgss_query_texts.stat pgss_query_texts.stat_bak
[postgres@xiongcc pg_stat_tmp]$ psql -xc "select * from pg_stat_statements limit 1"
-[ RECORD 1 ]-------+---------------------
userid              | 10
dbid                | 13892
toplevel            | t
queryid             | -6277613595553870050
query               | 
plans               | 0
total_plan_time     | 0
min_plan_time       | 0
max_plan_time       | 0
mean_plan_time      | 0
stddev_plan_time    | 0
calls               | 1
total_exec_time     | 0.29753100000000005
min_exec_time       | 0.29753100000000005
max_exec_time       | 0.29753100000000005
mean_exec_time      | 0.29753100000000005
stddev_exec_time    | 0
rows                | 1
shared_blks_hit     | 52
shared_blks_read    | 0
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0
blk_write_time      | 0
wal_records         | 0
wal_fpi             | 0
wal_bytes           | 0

临时文件

那现在还剩下为什么会写入大量的pgsql_tmp文件,pgsql_tmp我们知道是临时文件存放的地方,当在执行排序、HASH JOIN、中间结果存储、聚合等会用到临时文件,超过了work_mem就会溢出到磁盘,在事务和查询结束后会自动回收。

再次执行SQL,统计一下临时文件

postgres=# WITH tablespaces AS (
    SELECT
        spcname AS tbl_name,
        coalesce(nullif(pg_tablespace_location(oid), ''), (current_setting('data_directory') || '/base')) AS tbl_location
    FROM pg_tablespace
),
tablespace_suffix AS (
    SELECT
        tbl_name,
        tbl_location || '/pgsql_tmp' AS path
    FROM tablespaces
    WHERE tbl_name = 'pg_default'
    UNION ALL
    SELECT
        tbl_name,
        tbl_location || '/' || path || '/pgsql_tmp'
    FROM tablespaces, LATERAL pg_ls_dir(tbl_location) AS path
    WHERE path ~ ('PG_' || substring(current_setting('server_version') FROM '^(?:\d\.\d\d?|\d+)'))
),
stat AS (
    SELECT
        substring(file from '\d+\d') AS pid,
        tbl_name AS temp_tablespace,
        pg_size_pretty(sum(pg_size_bytes(size))) AS size
    FROM tablespace_suffix, LATERAL pg_ls_dir(path, true, false) AS file,
    LATERAL pg_size_pretty((pg_stat_file(path || '/' || file, true)).size) AS size
    GROUP BY pid, temp_tablespace
)
SELECT
    a.datname,
    a.pid,
    coalesce(size, '0 MB') AS temp_size_written,
    coalesce(temp_tablespace, 'not using temp files') AS temp_tablespace,
    a.application_name,
    a.client_addr,
    a.usename,
    (clock_timestamp() - a.query_start)::interval(0) AS duration,
    (clock_timestamp() - a.state_change)::interval(0) AS duration_since_state_change,
    trim(trailing ';' FROM left(query, 1000)) AS query,
    a.state,
    a.wait_event_type || ':' || a.wait_event AS wait
FROM pg_stat_activity AS a
LEFT JOIN stat ON a.pid = stat.pid::int
WHERE a.pid != pg_backend_pid() and a.pid = 6105
ORDER BY temp_size_written DESC;
-[ RECORD 1 ]---------------+------------------------
datname                     | postgres
pid                         | 6105
temp_size_written           | 1108 MB
temp_tablespace             | pg_default
application_name            | psql
client_addr                 | 
usename                     | postgres
duration                    | 00:05:53
duration_since_state_change | 00:05:48
query                       | explain analyze select count(*) from pg_stat_statements;
state                       | idle
wait                        | IO:BufFileRead

可以看到生成了大约1GB的临时文件,也可以通过设置log_temp_files在日志中观察临时文件。如之前的分析,具体的查询是放在外部文件pgss_query_texts.stat中的,当查询文本很大的时候,中间结果也很大,就会写入到临时文件中。这也是为什么执行计划显示 actual time=4145.352..4145.353的原因,因为actual time的start-up是从启动executor直到扫描到符合where语句的第一条结果为止,都花在了大量的临时文件上,而运行时间running-time几乎没有。

postgres=# explain analyze select count(*) from pg_stat_statements;
                                                         QUERY PLAN                                                        

  ---------------------------------------------------------------------------------------------------------------------------
--
 Aggregate  (cost=12.50..12.51 rows=1 width=8) (actual time=4145.352..4145.353 rows=1 loops=1)
   ->  Function Scan on pg_stat_statements  (cost=0.00..10.00 rows=1000 width=0) (actual time=3809.405..4144.071 rows=3199 loops=1
)
 Planning Time: 0.113 ms
 Execution Time: 4411.721 ms
(4 rows)

那统计一下查询的长度

postgres=# select length(query) from pg_stat_statements order by 1 desc limit 5;
 length 
--------
 389030     
 389030
 389030
 389030
 389030
(5 rows)

DBA表示惊呆了😮 38万,通过hexdump,原来里面装的SQL都是上万个绑定变量....

Image

而毫秒就出的实例,最大的长度才655,所以这也是为什么这位同事说重置了pg_stat_statements的内容后能好一阵子,但是没过多久又不对了,因为SQL还是那些SQL,时间一久量又上来了,通过对比大小,这个影响的实例的pgss_query_texts.stat大小是1.1GB,而正常的才几十兆。

既然知晓了问题原因,解决办法也好处理,调一下参数即可

postgres=# show track_activity_query_size ;
 track_activity_query_size 
---------------------------
 1kB
(1 row)

track_activity_query_size参数的意思是当查询超过多少个字节时,在记录到pg_stat_activity和pg_stat_statements就截断,值越大也会耗费更多的内存。在我们生产中,我们设置成了10KB,因此可以将这个值调小,当然坏处就是SQL可能被截断了,无法看到全貌,分析问题时会带来一定困扰。

“

Sets the truncation threshold of queries in pg_stat_activity (and pg_stat_statements). Increase it if you have really long queries which are being cut off, but there is significant extra memory usage for keeping longer queries.

与之类似的,在JDBC里面也有参数的限制,入参不能超过32767个,https://github.com/pgjdbc/pgjdbc/issues/1311,超过就会报如下异常

“

Hibernate java.io.IOException: Tried to send an out-of-range integer as a 2-byte value

FetchSize也要合理设置,一不小心JVM就OOM了。

小结

真是一个有趣的案例。感谢这位与PostgreSQL八字不合的同事又贡献了一个素材 ~

参考

https://www.postgresql.org/docs/current/pgstatstatements.html

https://developer.aliyun.com/article/603965

https://arctype.com/blog/postgresql-hooks/

https://supabase.com/blog/2021/07/01/roles-postgres-hooks

https://dba.stackexchange.com/questions/244955/does-enabling-pg-stat-statements-reduce-disk-space

https://dba.stackexchange.com/questions/218351/postgres-pg-stat-statements-directory