pg_stat_statements又出问题了！
xiongcc约 15 分钟前言
上周的时候分享了一篇生产案例 👉🏻 pg_stat_statements的有趣案例，业务查询里面传了上万个绑定变量导致CPU不定时冲高，最后给出的解决办法是调整track_activity_query_size参数，让采集的查询截断至指定长度。
但是上周五同事改了参数并重置了pg_stat_statements视图之后，今天来看发现长度依旧是那么长，难道之前的分析有问题？
本着严谨的态度，怕有小伙伴看了之前的文章之后下去试验发现没效果，误人子弟，所以今晚就赶着写了出来。
分析
回顾一下之前的分析：
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.
为什么当时会给出这个结论呢，原因是我在一些文档上看到了这些，比如著名的 https://postgresqlco.nf/，里面这样写到
“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.
在9.2的官方文档里面也提到 Text of a representative statement (up to track_activity_query_size bytes)，虽然版本有点远古
实验
让我们试验一下，将track_activity_query_size调到最小
postgres=# show track_activity_query_size ;
track_activity_query_size
---------------------------
100B
(1 row)
然后随便构造一个超过100字节的查询，可以看到pg_stat_activity确实被截断了
postgres=# select query from pg_stat_activity where pid = '30077';
query
-----------------------------------------------------------------------------------------------------
insert into t1 values(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(
(1 row)
但是pg_stat_statements依旧坚挺...此处省略800字
postgres=# select query from pg_stat_statements where queryid='-3856530648391879273';
-[ RECORD 1 ]--------------------------------------------------------------------------------------------------------------------
query | insert into t1 values($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12),($13,$14),($15,$16),($17,$18),($19,$20),($21,$22),($23,$24),($25,$26),($27,$28),($29,$30),($31,$32),($33,$34),($35,$36),($37,$38),($39,$40),($41,$42),($43,$44),($45,$46),($47,$48),($49,$50),($51,$52),($53,$54),($55,$56),($57,$58),($59,$60),($61,$62),($63,$64),($65,$66),($67,$68),($69,$70),($71,$72),($73,$74),($75,$76),($77,$78),($79,$80),($81,$82),($83,$84),($85,$86),($87,$88),($89,$90),($91,$92),($93,$94),($95,$96),($97,$98),($99,$100),($101,$102),($103,$104),($105,$106),($107,$108),($109,$110),($111,$112),($113,$114),($115,$116),($117,$118),($119,$120),($121,$122),($123,$124),($125,$126),($127,$128),($129,$130),($131,$132),($133,$134),($135,$136),($137,$138),($139,$140),($141,$142),($143,$144),($145,$146),($147,$148),($149,$150),($151,$152),($153,$154),($155,$156),($157,$158),($159,$160),($161,$162),($163,$164),($165,$166),($167,$168),($169,$170),($171,$172),($173,$174),($175,$176),($177,$178),($179,$180),($181,$182),($183,$184),($185,$186),($187,$188),($189,$190),($191,$192),($193,$194),($195,$196),($197,$198),($199,$200),($201,$202),($203,$204),($205,$206),($207,$208),($209,$210),($211,$212),($213,$214),($215,$216),($217,$218),($219,$220),($221,$222),($223,$224),($225,$226),($227,$228),($229,$230),($231,$232),($233,$234),($235,$236),($237,$238),($239,$240),($241,$242),($243,$244),($245,$246),($247,$248),($249,$250),($251,$252),($253,$254),($255,$256),($257,$258),($259,$260),($261,$262),($263,$264),($265,$266),($267,$268),($269,$270),($271,$272),($273,$274),($275,$276),($277,$278),($279,$280),($281,$282),($283,$284),($285,$286),($287,$288),($289,$290),($291,$292),($293,$294),($295,$296),($297,$298),($299,$300),($301,$302),($303,$304),($305,$306),($307,$308),($309,$310),($311,$312),($313,$314),($315,$316),($317,$318),($319,$320),($321,$322),($323,$324),($325,$326
...
...
通过继续摸索，我在邮件里找到这样一条，并且还是最近5月2号的 Re: limiting collected query text length in pg_stat_statements
“pg_stat_statements used to truncate the query text to track_activity_query_size, but that limitation was removed when the query texts were moved to the external query file.
pg_stat_statements以前会把查询文本截断至track_activity_query_size，但是当查询文本被移到外部查询文件时，这个限制被移除了。
也就是说在高版本里面的行为，这个参数又不进行限制了。并且这位兄台的问题和此次案例十分类似，查询pg_stat_statements会影响到普通的查询！
“With the pg_stat_statements.max is set to 1000 statements just querying the table stats table seems to impact the running statements! I have temporarily staved off the issue by reducing the max to 250 statements, and I have made recommendations to the development team to cut down the number of values clauses. However, it seems to me that the ability to truncate the captured query would be a useful feature.
在pg_stat_statements.max被设置为1000条语句的情况下，仅仅查询stats表似乎就会影响到运行中的语句! 我通过将最大语句数减少到250条，暂时避免了这个问题，而且我已经向开发团队提出建议，以减少子句的数量。然而，在我看来，截断捕获的查询的能力仍是一个有用的功能。
原理解析
继续思考一下，track_activity_query_size参数的原理是什么？
其实这个参数的作用是控制在shared_buffers中分配多少内存用于存储查询SQL
/*
* Allocate storage for local copy of state data. We can presume that
* none of these requests overflow size_t, because we already calculated
* the same values using mul_size during shmem setup. However, with
* probably-silly values of pgstat_track_activity_query_size and
* max_connections, the localactivity buffer could exceed 1GB, so use
* "huge" allocation for that one.
*/
localtable = (LocalPgBackendStatus *)
MemoryContextAlloc(backendStatusSnapContext,
sizeof(LocalPgBackendStatus) * NumBackendStatSlots);
localappname = (char *)
MemoryContextAlloc(backendStatusSnapContext,
NAMEDATALEN * NumBackendStatSlots);
localclienthostname = (char *)
MemoryContextAlloc(backendStatusSnapContext,
NAMEDATALEN * NumBackendStatSlots);
localactivity = (char *)
MemoryContextAllocHuge(backendStatusSnapContext,
pgstat_track_activity_query_size * NumBackendStatSlots);
举个栗子，目前track_activity_query_size是100
postgres=# select * from pg_shmem_allocations where name ='Backend Activity Buffer';
name | off | size | allocated_size
-------------------------+-----------+-------+----------------
Backend Activity Buffer | 146768896 | 13000 | 13056
(1 row)
调成1000之后，再看看分配的Buffer
postgres=# select * from pg_shmem_allocations where name ='Backend Activity Buffer';
name | off | size | allocated_size
-------------------------+-----------+--------+----------------
Backend Activity Buffer | 146768896 | 130000 | 130048
(1 row)
很清晰，size也扩大了10倍。另外还需要了解的是结构体PgBackendStatus，每一个后端进程都会在共享内存中维护这样一个结构体，主要记录了一些自身状态，辅助进程比如autovacuum/bgwriter等，同样也有。
/* ----------
* PgBackendStatus
*
* Each live backend maintains a PgBackendStatus struct in shared memory
* showing its current activity. (The structs are allocated according to
* BackendId, but that is not critical.) Note that the collector process
* has no involvement in, or even access to, these structs.
*
* Each auxiliary process also maintains a PgBackendStatus struct in shared
* memory.
* ----------
*/
typedef struct PgBackendStatus
{
/*
* To avoid locking overhead, we use the following protocol: a backend
* increments st_changecount before modifying its entry, and again after
* finishing a modification. A would-be reader should note the value of
* st_changecount, copy the entry into private memory, then check
* st_changecount again. If the value hasn't changed, and if it's even,
* the copy is valid; otherwise start over. This makes updates cheap
* while reads are potentially expensive, but that's the tradeoff we want.
*
* The above protocol needs memory barriers to ensure that the apparent
* order of execution is as it desires. Otherwise, for example, the CPU
* might rearrange the code so that st_changecount is incremented twice
* before the modification on a machine with weak memory ordering. Hence,
* use the macros defined below for manipulating st_changecount, rather
* than touching it directly.
*/
int st_changecount; /* The entry is valid iff st_procpid > 0, unused if st_procpid == 0 */
int st_procpid;
/* Type of backends */
BackendType st_backendType;
/* Times when current backend, transaction, and activity started */
TimestampTz st_proc_start_timestamp;
TimestampTz st_xact_start_timestamp;
TimestampTz st_activity_start_timestamp;
TimestampTz st_state_start_timestamp;
/* Database OID, owning user's OID, connection client address */
Oid st_databaseid;
Oid st_userid;
SockAddr st_clientaddr;
char *st_clienthostname; /* MUST be null-terminated */
/* Information about SSL connection */
bool st_ssl;
PgBackendSSLStatus *st_sslstatus;
/* Information about GSSAPI connection */
bool st_gss;
PgBackendGSSStatus *st_gssstatus;
/* current state */
BackendState st_state;
/* application name; MUST be null-terminated */
char *st_appname;
/*
* Current command string; MUST be null-terminated. Note that this string
* possibly is truncated in the middle of a multi-byte character. As
* activity strings are stored more frequently than read, that allows to
* move the cost of correct truncation to the display side. Use
* pgstat_clip_activity() to truncate correctly.
*/
char *st_activity_raw;
/*
* Command progress reporting. Any command which wishes can advertise
* that it is running by setting st_progress_command,
* st_progress_command_target, and st_progress_param[].
* st_progress_command_target should be the OID of the relation which the
* command targets (we assume there's just one, as this is meant for
* utility commands), but the meaning of each element in the
* st_progress_param array is command-specific.
*/
ProgressCommandType st_progress_command;
Oid st_progress_command_target;
int64 st_progress_param[PGSTAT_NUM_PROGRESS_PARAM];
/* query identifier, optionally computed using post_parse_analyze_hook */
uint64 st_query_id;
} PgBackendStatus;
其中st_activity_raw就是记录的具体SQL。👇🏻 被截断到了1000字节
Breakpoint 1, pgstat_clip_activity (
raw_activity=0x2c58e00 "select length('insert into t values(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'tes") at backend_status.c:1131
在pg_stat_statements的实现中，将数据存储的逻辑在pgss_store中，而格式化查询的逻辑在CleanQuerytext()中，比如处理无效空格
/*
* Given a possibly multi-statement source string, confine our attention to the
* relevant part of the string.
*/
const char *
CleanQuerytext(const char *query, int *location, int *len)
{
int query_location = *location;
int query_len = *len; /* First apply starting offset, unless it's -1 (unknown). */
if (query_location >= 0)
{
Assert(query_location <= strlen(query));
query += query_location;
/* Length of 0 (or -1) means "rest of string" */
if (query_len <= 0)
query_len = strlen(query);
else
Assert(query_len <= strlen(query));
}
else
{
/* If query location is unknown, distrust query_len as well */
query_location = 0;
query_len = strlen(query);
}
/*
* Discard leading and trailing whitespace, too. Use scanner_isspace()
* not libc's isspace(), because we want to match the lexer's behavior.
*/
while (query_len > 0 && scanner_isspace(query[0]))
query++, query_location++, query_len--;
while (query_len > 0 && scanner_isspace(query[query_len - 1]))
query_len--;
*location = query_location;
*len = query_len;
return query;
}
打个断点看一下
(gdb) b CleanQuerytext
Breakpoint 1 at 0xaa669c: file queryjumble.c, line 64.
(gdb) info b
Num Type Disp Enb Address What
1 breakpoint keep y 0x0000000000aa669c in CleanQuerytext at queryjumble.c:64
可以看到我刚刚传入的那一长串SQL长度是4089个字节，需要注意的是GDB默认显式的字符串是截断的，需要设置一下 set print element 0
64 int query_location = *location;
(gdb) n
65 int query_len = *len;
(gdb) n
68 if (query_location >= 0)
(gdb)
71 query += query_location;
(gdb)
73 if (query_len <= 0)
(gdb)
91 while (query_len > 0 && scanner_isspace(query[query_len - 1]))
(gdb)
94 *location = query_location;
(gdb)
95 *len = query_len;
(gdb) p *len
$1 = 4089
(gdb) n
97 return query;
(gdb) set print element 0
(gdb) p query
$2 = 0x2a1a838 "insert into t values(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test'),(1,'test');"
因此不太严谨的改造方式之一就是在这个函数最后步骤，截断一下也好，或者其他方式，截断一下查询即可。
小结
通过这个小案例说明，还是自己手动实操验证一下才行，不同版本间的行为会有所差异。那么解决方式也需要相应改变一下：
参照上方的源码分析改造一下pg_stat_statements的代码 调小pg_stat_statements.max，让存储的条目变少 定时重置pg_stat_statements_reset() 从根源上治理，让开发不要传入这么多绑定变量，通过SQL审核平台进行监控告警
参考
https://stackoverflow.com/questions/59639684/why-does-postgresql-reserve-fixed-amount-of-memory-for-the-text-of-the-currently
https://postgresqlco.nf/doc/en/param/track_activity_query_size/
https://www.postgresql.org/message-id/SA0PR15MB39337CC1622DDFEC7D0E609F82C29%40SA0PR15MB3933.namprd15.prod.outlook.com
https://www.dazhuanlan.com/zjavax/topics/1600630