PostgreSQL慢查询SQL收集和解析

postgresql通过log_statement参数记录慢SQL语句

PostgreSQL可以不借助任何扩展实现对SQL日志的记录,主要依赖于两个参数,也即log_statement和log_min_duration_statement,

1,记录的sql类型
log_statement='all' 可以是none, ddl, mod, all

2,记录的sql执行时间阈值
log_min_duration_statement='1000',单位毫秒,记录超出该单位时间的log_statement中定义类型的SQL

以上两个参数规定了记录超出log_min_duration_statement时间的log_statement类型的SQL语句到日志文件中

3,PostgreSQL日志行前缀的格式,
log_line_prefix = '%m [%p] ' # special values:
             # %a = application name
            # %u = user name
            # %d = database name
            # %r = remote host and port
            # %h = remote host
            # %b = backend type
            # %p = process ID
            # %P = process ID of parallel group leader
            # %t = timestamp without milliseconds
            # %m = timestamp with milliseconds
            # %n = timestamp with milliseconds (as a Unix epoch)
            # %Q = query ID (0 if none or not computed)
            # %i = command tag
            # %e = SQL state
            # %c = session ID
            # %l = session line number
            # %s = session start timestamp
            # %v = virtual transaction ID
            # %x = transaction ID (0 if none)
            # %q = stop here in non-session
            # processes
            # %% = '%'
            # e.g. '<%u%%%d> '

需要注意的是,PostgreSQL慢日志信息是一个过程,有多行文本组成,每个步骤在日志里都是一行文本信息,大概步骤如下,
step 1,执行开始前,即被记入日志(log_statement生效)
step 2,语句执行的过程中,会涉及绑定变量解析等等
step 3,语句执行完成后,将duration记入日志
由于以上过程存在并发Session交叉写入的情况,因此要考虑如何解析(记录足够详细的log_line_prefix )。由于慢日志都以文本的方式分行存储,以上日志会存在交叉存储的场景,也即session1和Session2会并行地往log里写入日志信息,从而导致两者的日志交叉写入,类似于如下这样,真正写代码做过解析的都知道(如果不记录SessionID)这个难点。

    session1 begin
    session2 begin
    session1 execute
    session3 begin
    session2 execute
    session2 end
    session1 end
    session3 end
    :param file_name:
    :return

因此为了方便解析,需要记录尽可能详细的一些信息,比如远程主机名,session ID等信息,可以判断判断那些信息是某个客户端的某个session发起的。

 

通过auto_explain扩展记录慢查询日志

尽管可以通过log_statement记录到所谓的慢查询日志,但auto_explain可以记录慢查询的SQL语句以及执行计划信息,为了异常的诊断提供了更多的参考依据。
auto_explain 并没有 .sql 、.control 文件,所以是无法通过 create extension 来完成。需要通过设置 shared_preload_librariess 参数预先加载auto_explain到某些或者所有会话中。

###查看已加载的扩展

如果setting字段是否有auto_explain
select name, setting, pending_restart FROM pg_settings WHERE name = 'shared_preload_libraries';

###临时加载
  ###session级打开auto_plain,需要超级用户权限
  load 'auto_explain';
  ###设置SQL记录执行计划的时间阈值
  set auto_explain.log_min_duration = '200000'
  set auto_explain.log_analyze = true;
  当然如果是动态加载auto_explain,退出当前sql session则auto_explain失效。

###全局加载
  ##编辑配置文件$ vi postgresql.conf
  shared_preload_libraries = 'auto_explain' # (change requires restart),shared_preload_libraries 的修改需要重启数据库

##配置项
#------------------------------------------------------------------------------
# CUSTOMIZED OPTIONS
#------------------------------------------------------------------------------
# Add settings for extensions here
# auto_explain
auto_explain.log_min_duration = '100'
auto_explain.log_timing = on
auto_explain.log_verbose = on

###如何取消auto_explain
  根据上面配置,做反向操作,也即取消shared_preload_libraries中的auto_explain配置,取消auto_explain相关配置项,同样需要重启

 

pgbadger解析慢日志

通过以上两种方式,可以将PostgreSQL中会将慢日志写入PostgreSQL log文件中,但是PostgreSQL日志中也包含系统日志等一系列信息,因此解析PostgreSQL日志并不是一个太容易的工作。
这里采用pgBDger这个工具来实现日志的解析,pgbadger的安装和使用都非常简单,更多详情参考 https://github.com/darold/pgbadger

1.###自行安装相关依赖包
......

2.###下载最新版的pgbadger
wget https://github.com/darold/pgbadger/archive/refs/tags/v12.4.tar.gz

3.###解压缩
tar -xzvf v12.4.tar.gz

4.###Makefile PL创建Makefile文件
cd pgbadger-12.4
/pgbadger-12.4# perl Makefile.PL
    Checking if your kit is complete...
    Looks good
    Generating a Unix-style Makefile
    Writing Makefile for pgBadger
    Writing MYMETA.yml and MYMETA.json

5.###编译安装    
/pgbadger-12.4# perl Makefile.PL
    Checking if your kit is complete...
    Looks good
    Generating a Unix-style Makefile
    Writing Makefile for pgBadger
    Writing MYMETA.yml and MYMETA.json
    root@VM-20-15-ubuntu:/usr/local/postgresql_install_package/pgbadger-12.4# make && make install
    Makefile:899: You must install pod2markdown to generate README.md from doc/pgBadger.pod
    cp pgbadger blib/script/pgbadger
    "/usr/bin/perl" -MExtUtils::MY -e 'MY->fixin(shift)' -- blib/script/pgbadger
    echo "=head1 SYNOPSIS" > doc/synopsis.pod
    ./pgbadger --help >> doc/synopsis.pod
    echo "=head1 DESCRIPTION" >> doc/synopsis.pod
    sed -i.bak 's/ +$//g' doc/synopsis.pod
    rm doc/synopsis.pod.bak
    sed -i.bak '/^=head1 SYNOPSIS/,/^=head1 DESCRIPTION/d' doc/pgBadger.pod
    sed -i.bak '4r doc/synopsis.pod' doc/pgBadger.pod
    rm doc/pgBadger.pod.bak
    Manifying 1 pod document
    rm doc/synopsis.pod
    Makefile:899: You must install pod2markdown to generate README.md from doc/pgBadger.pod
    echo "=head1 SYNOPSIS" > doc/synopsis.pod
    ./pgbadger --help >> doc/synopsis.pod
    echo "=head1 DESCRIPTION" >> doc/synopsis.pod
    sed -i.bak 's/ +$//g' doc/synopsis.pod
    rm doc/synopsis.pod.bak
    sed -i.bak '/^=head1 SYNOPSIS/,/^=head1 DESCRIPTION/d' doc/pgBadger.pod
    sed -i.bak '4r doc/synopsis.pod' doc/pgBadger.pod
    rm doc/pgBadger.pod.bak
    Manifying 1 pod document
    Installing /usr/local/man/man1/pgbadger.1p
    Installing /usr/local/bin/pgbadger
    Appending installation info to /usr/local/lib/x86_64-linux-gnu/perl/5.34.0/perllocal.pod
    rm doc/synopsis.pod
6.###默认安装路径
/pgbadger-12.4# whereis pgbadger
    pgbadger: /usr/local/bin/pgbadger

7.###切换到PostgreSQL日志目录
/local/pgsql16/pg9000/log# ll
total 1204
drwxr-x--- 2 postgres postgres    4096 Oct 17 16:54 ./
drwxr-x--- 4 postgres postgres    4096 Oct 15 13:42 ../
-rw-r--r-- 1 root     root     1179610 Oct 17 16:54 out.html
-rwxr-x--- 1 postgres postgres    1443 Oct 15 14:01 pgsql.log*
-rw------- 1 postgres postgres    2877 Oct 15 21:19 postgresql-2024-10-15_142057.log
-rw------- 1 postgres postgres   16708 Oct 16 23:57 postgresql-2024-10-16_000000.log
-rw------- 1 postgres postgres    8273 Oct 17 16:02 postgresql-2024-10-17_000000.log

8.###运行pgbadger,后面可以跟一个或者多个PostgreSQL日志文件
/local/pgsql16/pg9000/log# pgbadger postgresql-2024-10-15_142057.log postgresql-2024-10-16_000000.log postgresql-2024-10-17_000000.log
[========================>] Parsed 27858 bytes of 27858 (100.00%), queries: 0, events: 69
LOG: Ok, generating html report...

9.###会将日志报告生成在当前目录下

可以看到pgbadger解析出来的日志报告非常详细,这里是auto_explain捕获到的慢查询的结果,包含了执行计划信息

这个是错误日志,包括SQL错误信息(解析失败,执行失败等等等等)

pgbadger解析出来的日志有多种维护的汇总和呈现,不限于以上两种截图中的内容,可以为日志分析提供给多个维度的参考。

 

以上简要总结了PostgreSQL中慢查询日志的记录和解析过程,通过对慢查询日志的记录和分析,可以为系统异常诊断提供可参考依据。