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,语句执行的过程中,会涉及变量的parser,rewrite,绑定变量解析等等已发个或者多个步骤(生成多行文本)
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相关配置项,同样需要重启
###auto_explain相关的参数
auto_explain相关参数
auto_explain.log_min_duration
log_min_duration是导致记录语句执行计划的最小的执行时间(以毫秒为单位)。如果设置为0,会记录所有的执行计划。默认值是-1,即不记录。比如,如果设置为250ms,即记录运行时间超过250ms的语句的执行计划(包含250ms)
auto_explain.log_analyze
布尔类型的值。如果设置为true,在记录的执行计划的时候,输出的内容是explain analyze的结果,而不是explain的结果。默认值是off。开启后对性会有影响,
auto_explain.log_buffers
布尔类型的值。控制是否统计在执行计划中,对buffer的使用统计信息。等价于explain buffers。默认是off的。该选项只有在开启了auto_explain.log_analyze后才有效。
auto_explain.log_timing
布尔类型的值。控制执行计划中是否统计每个节点的时间信息。等价于explain timing。在有些系统中,重复地读取系统锁信息会降低查询性能。一般不建议开启。要想生效,必须先开启auto_explain.log_analyze。默认设置是on。
auto_explain.log_triggers
布尔类型的值。在记录执行计划时包含触发器执行统计信息。这个参数没有作用,除非auto_explain.log_analyze被启用。该参数默认关闭。只有超级用户才能更改此设置。
auto_explain.log_verbose
布尔类型的值。控制在记录执行计划时是否打印详细信息;它相当于冗长的EXPLAIN VERBOSE选项。该参数默认关闭。只有超级用户才能更改此设置。
auto_explain.log_format
枚举类型。定义explain的输出格式。支持的格式有:text、xml、json、yaml。默认是text。
auto_explain.log_nested_statements
布尔类型的值。考虑对嵌套语句(在函数中执行的语句)进行日志记录。当它关闭时,只记录顶级查询计划。该参数默认关闭。只有超级用户才能更改此设置。
auto_explain.sample_rate
real类型的值。只解释每个会话中的一小部分语句。默认值是1,表示解释所有查询。在嵌套语句的情况下,要么全部解释,要么全部不解释。只有超级用户才能更改此设置。
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.gz3.###解压缩 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
/pgbadger-12.4# make && makeinstall 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 1716:54 ./ drwxr-x--- 4 postgres postgres 4096 Oct 1513:42 ../ -rw-r--r-- 1 root root 1179610 Oct 1716:54 out.html -rwxr-x--- 1 postgres postgres 1443 Oct 1514:01 pgsql.log* -rw------- 1 postgres postgres 2877 Oct 1521:19 postgresql-2024-10-15_142057.log -rw------- 1 postgres postgres 16708 Oct 1623:57 postgresql-2024-10-16_000000.log -rw------- 1 postgres postgres 8273 Oct 1716: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.###会将日志报告out.html生成在当前目录下
可以看到pgbadger解析出来的日志报告非常详细,这里是auto_explain捕获到的慢查询的结果,包含了执行计划信息
这个是错误日志,包括SQL错误信息(解析失败,执行失败等等等等)
pgbadger解析出来的日志有多种维护的汇总和呈现,不限于以上两种截图中的内容,可以为日志分析提供给多个维度的参考。
以上简要总结了PostgreSQL中慢查询日志的记录和解析过程,通过对慢查询日志的记录和分析,可以为系统异常诊断提供可参考依据。