PostgreSQL查询日志语句与执行耗时关联为单条记录方案验证

问题解答 #

配置问题说明 #

你遇到的SQL语句和执行耗时分行存储的情况，大概率是同时开启了log_statement = 'all'和log_min_duration_statement = 0两个配置导致的。如果关闭log_statement，只保留log_min_duration_statement = 0，PostgreSQL会自动将SQL语句和对应耗时合并到同一行日志输出，不需要额外做匹配。

关于session_line_num差值规律的正确性 #

这个规律在绝大多数无额外日志插入的正常执行场景下是成立的：当你同时开启上述两个配置时，PostgreSQL的csv日志默认会为每条执行的SQL输出两行独立日志：第一行是statement:开头的SQL语句内容，第二行紧跟duration:开头的执行耗时、执行计划等信息，同一会话内这两条日志的session_line_num确实相差1。
但要注意存在例外场景会打破这个规律：

• 语句执行过程中触发了警告、报错、通知类日志，这类日志会插入在statement行和duration行之间
• 同一会话内有其他系统级日志输出穿插在两条日志中间
  这类场景下session_line_num的差值会大于1，固定按+1匹配就会失效。

关于给出的查询的可靠性 #

你提供的查询可以覆盖大部分正常场景，但不能保证100%可靠，遇到上面提到的额外日志插入场景时，会出现匹配不到耗时、甚至匹配错其他语句耗时的问题。
如果需要更高的匹配准确率，可以参考优化逻辑：按会话分组后，用窗口函数匹配每个statement行之后最近的一条duration行，避免固定差值的限制，示例逻辑如下：

WITH log_with_rank AS (
    SELECT 
        session_id,
        session_line_num,
        message,
        -- 标记当前行是语句还是耗时
        CASE WHEN message LIKE 'statement%' THEN 'sql' 
             WHEN message LIKE 'duration%' THEN 'dur' 
        END AS log_type,
        -- 给同一会话内的sql行打分组标记
        SUM(CASE WHEN message LIKE 'statement%' THEN 1 ELSE 0 END) 
            OVER (PARTITION BY session_id ORDER BY session_line_num) AS sql_group
    FROM postgres_log
    WHERE message LIKE 'statement%' OR message LIKE 'duration%'
)
SELECT 
    session_id,
    MAX(CASE WHEN log_type = 'sql' THEN session_line_num END) AS sql_line_num,
    MAX(CASE WHEN log_type = 'sql' THEN message END) AS sql_statement,
    MAX(CASE WHEN log_type = 'dur' THEN message END) AS duration
FROM log_with_rank
GROUP BY session_id, sql_group;

另外如果你的PostgreSQL版本>=12，也可以直接开启jsonlog格式的日志输出，每条SQL的执行信息、耗时都会被整合到同一条JSON日志中，使用起来更省心。

内容的提问来源于stack exchange，提问作者Oto Shavadze