PostgreSQL 检查点性能影响及源码分析 - 4
背景
数据库可靠性从何而来？
数据库崩溃后如何恢复，从什么位置开始恢复？
数据库检查点是什么？
检查点要干些什么？
为什么脏数据较多时，检查点会对性能有一定的影响？
什么是full page write？
相信这些问题是搞数据库的同学都想搞明白的。
接下里的一系列文章，围绕检查点展开讲解，讲一讲检查点的原理，以及为什么脏数据较多是，它会对数据库产生一定的性能影响。
正文
这一篇主要谈一下和检查点相关的几个跟踪。
1. 锁等待次数和时间的跟踪。
2. 刷新缓存相关函数的时间跟踪。
从这些跟踪结果来反映检查点对数据库性能的影响。
先整理一下检查点相关的一些探针，如果不能满足跟踪的需求，可以再自定义添加：
刷事务提交日志相关的探针结构，了解结构对我们计算时间很有帮助：
CheckPointCLOG@src/backend/access/transam/clog.c
TRACE_POSTGRESQL_CLOG_CHECKPOINT_START(true);
TRACE_POSTGRESQL_CLOG_CHECKPOINT_DONE(true);
刷子事务相关的探针：
CheckPointSUBTRANS@src/backend/access/transam/subtrans.c
TRACE_POSTGRESQL_SUBTRANS_CHECKPOINT_START(true);
TRACE_POSTGRESQL_SUBTRANS_CHECKPOINT_DONE(true);
刷多事务相关的探针：
CheckPointMultiXact@src/backend/access/transam/multixact.c
TRACE_POSTGRESQL_MULTIXACT_CHECKPOINT_START(true);
TRACE_POSTGRESQL_MULTIXACT_CHECKPOINT_DONE(true);
刷Buffer相关的探针：
CheckPointBuffers(flags)@src/backend/storage/buffer/bufmgr.c
TRACE_POSTGRESQL_BUFFER_CHECKPOINT_START(flags); // buffer检查点开始
{ -- 遍历BUFFER区，将头信息need checkpoint的块刷入磁盘
BufferSync(flags) // 与第一个trace之间包含遍历整个buffer区,增加脏块头信息need checkpoint
TRACE_POSTGRESQL_BUFFER_SYNC_START(NBuffers, num_to_write); // 开始sync buffer
{ -- sync单个buffer
SyncOneBuffer
FlushBuffer
TRACE_POSTGRESQL_BUFFER_FLUSH_START(buf->tag.forkNum, // 单个buffer块, flush开始
buf->tag.blockNum,
reln->smgr_rnode.node.spcNode,
reln->smgr_rnode.node.dbNode,
reln->smgr_rnode.node.relNode);
TRACE_POSTGRESQL_BUFFER_FLUSH_DONE(buf->tag.forkNum, // 单个buffer块, flush结束
buf->tag.blockNum,
reln->smgr_rnode.node.spcNode,
reln->smgr_rnode.node.dbNode,
reln->smgr_rnode.node.relNode);
}
TRACE_POSTGRESQL_BUFFER_SYNC_WRITTEN(buf_id); // 单个buffer块, writeten结束
} // SYNC_START和SYNC_WRITTEN之间是单个buffer的writter时间
// BufferSync末端，缓存区的need checkpointer的脏块全部written完毕。
TRACE_POSTGRESQL_BUFFER_SYNC_DONE(NBuffers, num_written, num_to_write);
} // BufferSync结束
TRACE_POSTGRESQL_BUFFER_CHECKPOINT_SYNC_START();
// 调用smgrsync(); // 前面的write操作持久化到磁盘。
TRACE_POSTGRESQL_BUFFER_CHECKPOINT_DONE();
需要用到的probe name如下：
probe checkpoint__start(int);
probe clog__checkpoint__start(bool);
probe clog__checkpoint__done(bool);
probe subtrans__checkpoint__start(bool);
probe subtrans__checkpoint__done(bool);
probe multixact__checkpoint__start(bool);
probe multixact__checkpoint__done(bool);
probe buffer__checkpoint__start(int);
probe buffer__sync__start(int, int);
probe buffer__flush__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
probe buffer__flush__done(ForkNumber, BlockNumber, Oid, Oid, Oid);
probe buffer__sync__written(int);
probe buffer__sync__done(int, int, int);
probe buffer__checkpoint__sync__start();
probe buffer__checkpoint__done();
probe checkpoint__done(int, int, int, int, int);
含义请参考
http://www.postgresql.org/docs/devel/static/dynamic-trace.html
src/backend/utils/probes.d
src/backend/utils/probes.h
使用stap统计他们开始和结束的时间区间，对于sync和flush单个buffer统计耗时柱状分布。
stap -v 11111 -e '
global var, stat_var, tmp;
probe process("/opt/pgsql/bin/postgres").mark("checkpoint__start") {
/* clear data */
delete var
delete stat_var
delete tmp
var[pid(),0] = gettimeofday_us()
printf("checkpoint__start pid:%d, us_epoch: %d\n", pid(), var[pid(),0])
}
probe process("/opt/pgsql/bin/postgres").mark("clog__checkpoint__start") {
var[pid(),1] = gettimeofday_us()
}
probe process("/opt/pgsql/bin/postgres").mark("clog__checkpoint__done") {
var[pid(),2] = gettimeofday_us()
printf("clog__checkpoint__done us: %d\n", var[pid(),2]-var[pid(),1])
}
probe process("/opt/pgsql/bin/postgres").mark("subtrans__checkpoint__start") {
var[pid(),3] = gettimeofday_us()
}
probe process("/opt/pgsql/bin/postgres").mark("subtrans__checkpoint__done") {
var[pid(),4] = gettimeofday_us()
printf("subtrans__checkpoint__done us: %d\n", var[pid(),4]-var[pid(),3])
}
probe process("/opt/pgsql/bin/postgres").mark("multixact__checkpoint__start") {
var[pid(),5] = gettimeofday_us()
}
probe process("/opt/pgsql/bin/postgres").mark("multixact__checkpoint__done") {
var[pid(),6] = gettimeofday_us()
printf("multixact__checkpoint__done us: %d\n", var[pid(),6]-var[pid(),5])
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__checkpoint__start") {
var[pid(),7] = gettimeofday_us()
tmp[pid(),1] = $flags /* bitwise flags used to distinguish different checkpoint types */
printf("buffer__checkpoint__start flags: %d\n", tmp[pid(),1])
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__sync__start") {
var[pid(),8] = gettimeofday_us()
tmp[pid(),2] = $NBuffers /* number buffers */
tmp[pid(),3] = $num_to_write /* dirty buffers */
printf("buffer__sync__start num_buffers: %d, dirty_buffers: %d\n", tmp[pid(),2], tmp[pid(),3])
printf("scan buffers, lock bufheader one-by-one, add need chkpoint flag for dirty buffer: total us %d \n", var[pid(),8] - var[pid(),7])
}
/* start loop scan buffers */
probe process("/opt/pgsql/bin/postgres").mark("buffer__flush__start") {
var[pid(),9] = gettimeofday_us()
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__flush__done") {
var[pid(),10] = gettimeofday_us()
stat_var[pid(),1] <<< var[pid(),10] - var[pid(),9]
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__sync__written") {
var[pid(),11] = gettimeofday_us()
stat_var[pid(),2] <<< var[pid(),11] - var[pid(),10]
}
/* end loop scan buffers */
probe process("/opt/pgsql/bin/postgres").mark("buffer__sync__done") {
var[pid(),12] = gettimeofday_us()
tmp[pid(),7] = $NBuffers /* number buffers */
tmp[pid(),8] = $num_written /* actual written buffers */
tmp[pid(),9] = $num_to_write /* expect dirty buffers need flush */
if ( @count(stat_var[pid(),1]) > 0 ) {
printf("buffer__flush us min: %d, max: %d, avg: %d, sum: %d, count: %d\n", @min(stat_var[pid(),1]), @max(stat_var[pid(),1]), @avg(stat_var[pid(),1]), @sum(stat_var[pid(),1]), @count(stat_var[pid(),1]) )
print(@hist_log(stat_var[pid(),1]))
}
if ( @count(stat_var[pid(),2]) > 0 ) {
printf("buffer__sync us min: %d, max: %d, avg: %d, sum: %d, count: %d\n", @min(stat_var[pid(),2]), @max(stat_var[pid(),2]), @avg(stat_var[pid(),2]), @sum(stat_var[pid(),2]), @count(stat_var[pid(),2]) )
print(@hist_log(stat_var[pid(),2]))
}
printf("buffer__sync__done num_buffers: %d, actual_written_buffers: %d, dirty_buffers: %d\n", tmp[pid(),7], tmp[pid(),8], tmp[pid(),9])
printf("buffer__sync__done us: %d\n", var[pid(),12] - var[pid(),8])
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__checkpoint__sync__start") {
var[pid(),13] = gettimeofday_us()
}
probe process("/opt/pgsql/bin/postgres").mark("buffer__checkpoint__done") {
var[pid(),14] = gettimeofday_us()
printf("buffer__checkpoint__done sync us: %d\n", var[pid(),14] - var[pid(),13])
}
probe process("/opt/pgsql/bin/postgres").mark("checkpoint__done") {
var[pid(),15] = gettimeofday_us()
printf("checkpoint__done pid:%d, us_epoch: %d\n", pid(), var[pid(),15])
printf("checkpoint__done us: %d\n", var[pid(),15] - var[pid(),0])
/* clear data */
delete var
delete stat_var
delete tmp
}'
执行开始：
Pass 1: parsed user script and 111 library script(s) using 209424virt/36924res/3164shr/34644data kb, in 250usr/40sys/283real ms.
Pass 2: analyzed script: 22 probe(s), 7 function(s), 4 embed(s), 3 global(s) using 214056virt/42604res/4212shr/39276data kb, in 60usr/100sys/177real ms.
Pass 3: translated to C into "/tmp/stapDx3Mm2/stap_9b2d08e0dae6cce58d0357dbfb7496d6_10956_src.c" using 214056virt/42924res/4532shr/39276data kb, in 10usr/80sys/99real ms.
Pass 4: compiled C into "stap_9b2d08e0dae6cce58d0357dbfb7496d6_10956.ko" in 2220usr/490sys/2691real ms.
Pass 5: starting run.
同时执行pgbench做压力测试：
$ vi test.sql
\setrandom id 1 50000000
update tbl set info=now(),crt_time=now() where id=:id;
$ pgbench -M prepared -n -r -f ./test.sql -P 5 -c 26 -j 26 -T 10000000
progress: 5.0 s, 35426.2 tps, lat 0.729 ms stddev 0.616
progress: 10.0 s, 41056.1 tps, lat 0.631 ms stddev 0.556
progress: 15.0 s, 41447.5 tps, lat 0.625 ms stddev 0.546
progress: 20.0 s, 41920.3 tps, lat 0.618 ms stddev 0.542
progress: 25.0 s, 42192.7 tps, lat 0.614 ms stddev 0.510
progress: 30.0 s, 42177.1 tps, lat 0.614 ms stddev 0.496
progress: 35.0 s, 42974.5 tps, lat 0.603 ms stddev 0.417
progress: 40.0 s, 42003.3 tps, lat 0.617 ms stddev 0.504
progress: 45.0 s, 42467.8 tps, lat 0.610 ms stddev 0.498
......
提取其中一次跟踪到的checkpoint结果如下：
checkpoint__start pid:29658, us_epoch: 1431051835987299
clog__checkpoint__done us: 43383
subtrans__checkpoint__done us: 3170
multixact__checkpoint__done us: 6
buffer__checkpoint__start flags: 64
buffer__sync__start num_buffers: 524288, dirty_buffers: 153863
scan buffers, lock bufheader one-by-one, add need chkpoint flag for dirty buffer: total us 201192
// 从这里开始性能开始下降,也就是说,问题出在循环flush buffer的过程中, 但是性能会在约几秒后恢复, 并没有等到flush循环结束.
buffer__flush us min: 33, max: 48992, avg: 114, sum: 17671488, count: 153863
value |-------------------------------------------------- count
8 | 0
16 | 0
32 |@@@@@@ 12836
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 104806
128 |@@@@@@@@@@@@@@@@ 35471
256 | 597
512 | 34
1024 | 18
2048 | 17
4096 | 30
8192 | 46
16384 | 6
32768 | 2
65536 | 0
131072 | 0
buffer__sync us min: 1, max: 1717, avg: 2, sum: 334008, count: 153863
value |-------------------------------------------------- count
0 | 0
1 |@@@@@ 14633
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 134842
4 | 1857
8 | 2398
16 | 106
32 | 24
64 | 1
128 | 0
256 | 1
512 | 0
1024 | 1
2048 | 0
4096 | 0
buffer__sync__done num_buffers: 524288, actual_written_buffers: 153863, dirty_buffers: 153863
buffer__sync__done us: 268814089
buffer__checkpoint__done sync us: 2391
checkpoint__done pid:29658, us_epoch: 1431052105132986
checkpoint__done us: 269145687
分析：
简单的解释一下：
这里用的时间单位是微秒，即10的-6次方秒。
我的系统使用了32KB的数据块，配置了16GB的Shared Buffer, 因此可以看到num_buffers: 524288个32K的块刚好16GB。
检查点开始后有短暂的性能下降，但是不会持续到检查点结束，影响时间维持5秒左右。
progress: 255.0 s, 43021.9 tps, lat 0.602 ms stddev 0.434
progress: 260.0 s, 41028.6 tps, lat 0.631 ms stddev 0.512
progress: 265.0 s, 39556.4 tps, lat 0.655 ms stddev 0.631
progress: 270.0 s, 19495.2 tps, lat 1.331 ms stddev 2.350
progress: 275.0 s, 31672.6 tps, lat 0.818 ms stddev 0.915
progress: 280.0 s, 38465.6 tps, lat 0.674 ms stddev 0.656
progress: 285.0 s, 43365.8 tps, lat 0.597 ms stddev 0.629
整个过程的耗时：
1. 标记脏块需要遍历整个BUFFER区，耗时为201192微秒，0.2秒。
2. 遍历BUFFER区，调用FlushBuffer将脏块write到系统内核的区间，耗时268814089微秒，268.8秒，这里包含了大量的sleep。
(使用CheckpointWriteDelay调度sleep，可能产生多次休息，休息区间由几个参数决定，我在前面的文章也已经讲过了。)
CheckpointWriteDelay休息区间受到几个参数影响：
checkpoint_segments 越大 休息区间越大。
checkpoint_timeout 越大 休息区间越大。
checkpoint_completion_target 越大 休息区间越大。
checkpoint_completion_target 如果设置为1，那么下一个checkpoint会紧接着开始。
3. buffer write, sync柱状图到内核的统计柱状图信息。
buffer__flush us min: 33, max: 48992, avg: 114, sum: 17671488, count: 153863
buffer__sync us min: 1, max: 1717, avg: 2, sum: 334008, count: 153863
buffer write to内核， 一共耗时17671488微秒，17.67秒，注意这个才是真实的FlushBuffer的时间。
buffer sync to持久化存储， 一共耗时334008微秒，0.334秒。
以上操作的时间跨度为整个检查点区间的积累，所以是很分散的，而性能影响仅仅持续了检查点开始的前几秒，还需要从代码层面继续寻找原因，很大可能还是和lwlock锁有关系。
4. 将write到内核的数据sync到持久化存储的耗时2391微秒，0.002秒。
5. 整个checkpoint过程的耗时269145687微秒，269.1秒。
参考
1. http://blog.163.com/digoal@126/blog/static/1638770402015463252387/
2. http://www.postgresql.org/docs/devel/static/dynamic-trace.html
3. http://blog.163.com/digoal@126/blog/static/163877040201391883345365/
4. src/backend/utils/probes.d
5. src/backend/utils/probes.h