本文讲的是操作日志,非 WAL 日志。
文章目录
- 背景
- 日志模块原理
- Syslogger 核心模块
- 日志消息通信
- 日志轮转
- 问题一
- 问题二
- 问题三
- 问题四
- 问题五
- 存在的问题
- 刷盘性能
- 日志轮转
- 参考资料
背景
PG 的日志模块是一个相对独立的模块,主要功能就是打印用户的操作日志以及一些异常报错信息。本文仅讲述 logging_collector
参数开启的情况。
日志模块原理
Syslogger 核心模块
PG 有各种各样的进程,其中 syslogger
进程专门用于打印日志信息。
而其余进程打印日志的方法如出一辙:将需要打印的信息发送给 syslogger
进程,由其统一负责打印。
syslogger 的大体逻辑如下图所示:
- postmaster 进程在 SysLogger_Start 函数完成部分初始化;
- 由 postmaster 进程 fork 出 syslogger 进程;
- 进入 syslogger 的主逻辑函数 SysLoggerMain 中,大循环监听其他进程发送来的日志消息,处理打印逻辑。在大循环中同时也根据时间和大小,来判断是否进行日志轮转。
日志消息通信
PG 的其余进程如果有需要打印的日志,通常会调用 elog 或者 ereport 来打印。而这两个函数会将日志消息分成若干个 chunk 发送给 syslogger 进程,每个 chunk 的结构可参考下图(源码中的 PipeProtoChunk 结构)
- 开头两个 \0 ,表示是日志开头
- length:用于记录当前 chunk 的长度
- pid:发送该 chunk 的进程号
- is_last:是否是本条日志消息的最后一个 chunk;
- data:具体的日志消息。
- chunk 大小:PIPE_CHUNK_SIZE ,源码 define 出的一个值,由 OS 的 PIPE_BUF 决定。具体细节可参考这部分定义的代码。
注: PG 15 在 pipe 协议格式中做了一些变化,由 flags 代替 is_last 标记。
syslogger 在接收到日志消息后,将其按照 pid 进行分组,相同的 pid 说明日志消息来源于同一进程,将其组装起来,当收到包含 is_last 标记的最后一个 chunk 后,将整条日志消息打印到日志文件。
日志轮转
所谓日志轮转,指的就是不想继续写当前日志文件了,需要新找一个日志文件继续写日志。
PG 的日志轮转是一个坑非常多的地方,因为它由下面四个参数同时控制:
- log_filename :日志文件格式,我们以其设定为 postgres_%d_%h 为例,某个月 14 号 15 点的日志文件名就是 postgres_14_15.log
- log_rotation_age:如果距离当前日志文件已经超过设定的时间,那么就新开一个日志文件;
- log_rotation_size:如果距离当前日志文件还没有超过 log_rotation_age 设定的时间,但是已经超过了 log_rotation_size 设定的大小,那么就新开一个日志文件;
- log_truncate_on_rotation:是否在按时间轮转后做截断。即如果下一个日志文件的同名文件已经存在了,是否直接清空该文件并从头开始写;
这几个参数的具体使用可参考 PG 官方文档。看完上面的介绍,想必大家已经精通日志参数设置了,那么接下来做几道题检验自己的学习成果。
假如,我们按照以下值设定日志相关参数
log_filename='postgres_%d_%h.log'
log_rotation_age = 2h
log_rotation_size = 10MB
log_truncate_on_rotation = on
问题一
- Q:此时时间刚到 14 号下午 17 点 ,日志文件为 postgres_14_16.log,且大小为 5MB,请问接下来要写的日志文件是什么?
- A:postgres_14_16.log 。因为此时距离 15 点仅过了 1h,没有超过 log_rotation_age;大小并没有超过 log_rotation_size ,所以并不发生轮转。
问题二
- Q:此时时间为 14 号下午 16 点 30 分 ,日志文件为 postgres_14_16.log,且大小刚刚超过 10MB 到达 10.9MB,请问接下来要写的日志文件是什么?
- A:postgres_14_16.log 。因为 log_filename 参数的最小精度值就到小时,哪怕当前日志文件大小变成 1TB 也只会继续追加写这个文件。
问题三
- Q:此时时间刚到 14 号下午 17 点 ,日志文件为 postgres_14_16.log,且大小刚刚超过 10MB 到达 10.9MB,请问接下来要写的日志文件是什么?
- A:postgres_14_17.log 。因为满足 log_rotation_size 的轮转条件了。
问题四
- Q:此时时间刚到 14 号下午 17 点 ,日志文件为 postgres_14_16.log,且大小刚刚超过 10MB 到达 10.9MB,但是名为 postgres_14_17.log 的文件已经存在了(上个月日志创建的),那么是追加写还是覆盖写该文件?
- A:追加写,因为这是按大小轮转。
问题五
- Q:此时时间刚到 14 号下午 18 点 ,日志文件为 postgres_14_16.log,且大小只有 0.1MB。但是名为 postgres_14_18.log 的文件已经存在了,那么是追加写还是覆盖写该文件?
- A:覆盖写,log_rotation_age 强制触发按时间轮转逻辑。
上面问题都能搞懂,基本也没什么坑了。
存在的问题
刷盘性能
当前情况下,在 log_statement
参数设置成 all 时,性能下降会非常厉害。因为 PG 的日志在刷盘时的默认策略为:每写一行就刷盘。Linux 提供的刷盘模式可分为以下三种:
- _IOFBF:全缓冲模式,缓冲区写满后才刷盘
- _IOLBF:行缓冲模式,一行写满就刷盘
- _IONBF:不缓冲,直接刷
当前 PG 采用第二种行缓冲模式,优点是日志出来的即时性更高,缺点就是对性能有不小的影响。
日志轮转
日志轮转的逻辑设计虽然勉强算是合理的(不会丢日志),但是理解成本很高,且有可能出现某个日志文件存在了非常非常久(上一节问题 4 的变种),一直没被删掉,需要依赖人工手动删除。
参考资料
[1] https://www.postgresql.org/docs/current/logfile-maintenance.html
[2] https://github.com/postgres/postgres