PostgreSQL 查询随机执行需要几分钟

Posted 2023-04-15

【中文标题】PostgreSQL 查询随机执行需要几分钟

【英文标题】：PostgreSQL queries randomly takes minutes to execute

【发布时间】：2018-01-03 12:10:51

【问题描述】：

当多次（按顺序）运行同一个 SELECT 查询时，大约 10% 的查询需要几分钟才能执行（3 到 20 分钟）。 所有其他人在大约 100 毫秒内执行。 当长时间查询运行时，postgreSQL 进程占用 100% cpu。

我们在 Debian GNU/Linux 8.7 (jessie) 上运行 postgreSQL v9.4。 每天都会在数据库上运行 VACUUM ANALYZE。

在服务器端启用日志记录后，我们会看到以下条目：

成功场景：

2018-01-02 21:41:56 CET [15948]: [13776-1] STATEMENT:  BEGIN
2018-01-02 21:41:56 CET [15948]: [13777-1] LOG:  rewritten parse tree:
2018-01-02 21:41:56 CET [15948]: [13778-1] DETAIL:  (
        ... )
2018-01-02 21:41:56 CET [15948]: [13779-1] STATEMENT:  BEGIN
2018-01-02 21:41:56 CET [15948]: [13780-1] LOG:  duration: 0.114 ms  parse <unnamed>: BEGIN
2018-01-02 21:41:56 CET [15948]: [13781-1] LOG:  duration: 0.010 ms  bind <unnamed>: BEGIN
2018-01-02 21:41:56 CET [15948]: [13782-1] LOG:  execute <unnamed>: BEGIN
2018-01-02 21:41:56 CET [15948]: [13783-1] LOG:  duration: 0.015 ms
2018-01-02 21:41:56 CET [15948]: [13797-1] LOG:  plan:
2018-01-02 21:41:56 CET [15948]: [13798-1] DETAIL:     PLANNEDSTMT 
        ...
2018-01-02 21:41:56 CET [15948]: [13799-1] STATEMENT:  select 
        ... (the SELECT query)
2018-01-02 21:41:56 CET [15948]: [13800-1] LOG:  duration: 10.303 ms  bind S_21/C_24: select 
        ... (the SELECT query again)
2018-01-02 21:41:56 CET [15948]: [13801-1] DETAIL:  parameters: $1 = '149', $2 = '6'...(the query parameters)
2018-01-02 21:41:56 CET [15948]: [13802-1] LOG:  execute S_21/C_24: select 
        ... (the SELECT query again)
2018-01-02 21:41:56 CET [15948  ]: [13803-1] DETAIL:  parameters: $1 = '149', $2 = '6'...(the query parameters again)
2018-01-02 21:41:56 CET [15948]: [13804-1] LOG:  duration: 15.662 ms

失败的场景（长时间查询）：

2018-01-02 21:36:55 CET [15741]: [13060-1] STATEMENT:  BEGIN
2018-01-02 21:36:55 CET [15741]: [13061-1] LOG:  rewritten parse tree:
2018-01-02 21:36:55 CET [15741]: [13062-1] DETAIL:  (
        ... )
2018-01-02 21:36:55 CET [15741]: [13063-1] STATEMENT:  BEGIN
2018-01-02 21:36:55 CET [15741]: [13064-1] LOG:  duration: 0.107 ms  parse <unnamed>: BEGIN
2018-01-02 21:36:55 CET [15741]: [13065-1] LOG:  duration: 0.009 ms  bind <unnamed>: BEGIN
2018-01-02 21:36:55 CET [15741]: [13066-1] LOG:  execute <unnamed>: BEGIN
2018-01-02 21:36:55 CET [15741]: [13067-1] LOG:  duration: 0.016 ms
2018-01-02 21:36:55 CET [15741]: [13081-1] LOG:  plan:
2018-01-02 21:36:55 CET [15741]: [13082-1] DETAIL:     PLANNEDSTMT 
        ...
2018-01-02 21:36:55 CET [15741]: [13083-1] STATEMENT:  select 
        ... (the SELECT query)
2018-01-02 21:36:55 CET [15741]: [13084-1] LOG:  duration: 9.886 ms  bind S_20/C_27: select 
        ... (the SELECT query again)
2018-01-02 21:36:55 CET [15741]: [13085-1] DETAIL:  parameters: $1 = '149', $2 = '6'...(the query parameters)
2018-01-02 21:36:55 CET [15741]: [13086-1] LOG:  execute S_20/C_27: select 
    ... (the SELECT query again)
2018-01-02 21:36:55 CET [15741]: [13087-1] DETAIL:  parameters: $1 = '149', $2 = '6'...(the query parameters again)

**/!\--- LOOPING ABOUT 150 times ---/!\**
        2018-01-02 21:42:23 CET [15741]: [13088-1] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp15741.XX", size 9498636 (this value changes at every loop)
        2018-01-02 21:42:23 CET [15741]: [13089-1] STATEMENT:  select 
            ... (the SELECT query again)
**/!\--- END LOOP ---/!\**

2018-01-02 21:46:19 CET [15741]: [13340-1] LOG:  duration: 563668.493 ms
2018-01-02 21:46:19 CET [15741]: [13341-1] LOG:  duration: 0.026 ms  bind S_2: COMMIT
2018-01-02 21:46:19 CET [15741]: [13342-1] LOG:  execute S_2: COMMIT
2018-01-02 21:46:19 CET [15741]: [13343-1] LOG:  duration: 0.155 ms
2018-01-02 21:46:19 CET [15741]: [13344-1] LOG:  disconnection: session time: 0:10:23.538 user=xxx database=yyy host=127.0.0.1 port=60880                    

查看执行计划时，我们看到： - 所有 OK 查询都有相同的计划 - 所有 NOK（长期）查询都有相同的计划 - OK 和 NOK 计划略有不同：

        'total_cost' values (near but different values)
        ...
        TARGETENTRY 
            :expr 
                VAR 
                :varno 65000 ---------> differs
                :varattno 3  ---------> differs
                :vartype 20 
                :vartypmod -1 
                :varcollid 0 
                :varlevelsup 0 
                :varnoold 10  ---------> differs
                :varoattno 1 
                :location 2459 ---------> differs
                
        ... 
        :args (...
        PARAM | RELABELTYPE | CONST ---------> differs, always CONST for OK queries, always PARAM | RELABELTYPE for NOK queries
        ...
        

添加了其他信息： - Autovacuum 已关闭（每晚安排一次） - pg_stat_reset() 已运行 + ANALYZE（pbm 仍然存在） - 主表统计数据已增加 (500)，但 pbm 仍然存在。

此 pbm 出现在 Alfresco (5.1g) 环境中（使用 alfresco seach API），但我们无法通过直接 sql 查询重现此 pbm。

为这样的 SELECT 查询使用这么多临时文件有意义吗？

查询：

select
node.id as id 
from alf_node node 
where node.type_qname_id <> 149 
AND node.store_id = 6 
AND ( 
node.id IN 
    (
    select aspect.node_id 
    from alf_node_aspects aspect 
    where aspect.qname_id IN ( 260 )
    ) 
AND node.id IN 
    (
    select PROP.node_id 
    from alf_node_properties PROP 
    where (249 = PROP.qname_id) 
        AND PROP.string_value = 'Mandats' 
    ) 
AND node.id IN 
    (
    select PROP.node_id 
    from alf_node_properties PROP 
    where (245 = PROP.qname_id) 
        AND PROP.string_value = '1' 
    ) 
AND node.id IN 
    (
    select PROP.node_id 
    from alf_node_properties PROP 
    where (247 = PROP.qname_id) 
        AND PROP.string_value = '869637' 
    ) 
AND node.id IN 
    (
    select PROP.node_id 
    from alf_node_properties PROP 
    where (248 = PROP.qname_id) 
        AND PROP.string_value = 'AGF00619' 
    )
) 
order by node.audit_modified DESC;

有什么建议吗？ 谢谢， 文森特

【问题讨论】：

也许还有其他查询锁定了您的 SELECT 需要的东西？

这个临时文件是什么，为什么它会增长？ （对于 SELECT 语句？）

所以你有一个准备好的（动态？）查询，你重复调用。是否存在使用相同表的并发会话？ autovacuum 正在运行吗？表（或：索引）是否包含很多死行？也许您应该将查询添加到您的帖子中。

这个临时文件是什么，为什么它会增长？ （对于 SELECT 语句？）：好问题，我不知道...

【参考方案1】：

你试过了吗？：select pg_stat_reset();

【讨论】：

不，我认为这是由 VACCUM ANALYSE 完成的。不是吗？另一种选择是增加表的统计级别？