![](https://i-blog.csdnimg.cn/blog_migrate/85458856c557f88674ef240850c3be7f.png)
Postgres2015全国用户大会将于11月20至21日在北京丽亭华苑酒店召开。本次大会嘉宾阵容强大,国内顶级PostgreSQL数据库专家将悉数到场,并特邀欧洲、俄罗斯、日本、美国等国家和地区的数据库方面专家助阵:
- Postgres-XC项目的发起人铃木市一(SUZUKI Koichi)
- Postgres-XL的项目发起人Mason Sharp
- pgpool的作者石井达夫(Tatsuo Ishii)
- PG-Strom的作者海外浩平(Kaigai Kohei)
- Greenplum研发总监姚延栋
- 周正中(德哥), PostgreSQL中国用户会创始人之一
- 汪洋,平安科技数据库技术部经理
- ……
|
![]() |
这一篇主要谈一下和检查点相关的几个跟踪。
1. 锁等待次数和时间的跟踪。
2. 刷新缓存相关函数的时间跟踪。
从这些跟踪结果来反映检查点对数据库性能的影响。
先整理一下检查点相关的一些探针,如果不能满足跟踪的需求,可以再自定义添加:
刷事务提交日志相关的探针结构,了解结构对我们计算时间很有帮助:CheckPointCLOG@src/backend/access/transam/clog.cTRACE_POSTGRESQL_CLOG_CHECKPOINT_START(true);TRACE_POSTGRESQL_CLOG_CHECKPOINT_DONE(true);
刷子事务相关的探针:CheckPointSUBTRANS@src/backend/access/transam/subtrans.cTRACE_POSTGRESQL_SUBTRANS_CHECKPOINT_START(true);TRACE_POSTGRESQL_SUBTRANS_CHECKPOINT_DONE(true);
刷多事务相关的探针:CheckPointMultiXact@src/backend/access/transam/multixact.cTRACE_POSTGRESQL_MULTIXACT_CHECKPOINT_START(true);TRACE_POSTGRESQL_MULTIXACT_CHECKPOINT_DONE(true);
刷Buffer相关的探针:CheckPointBuffers(flags)@src/backend/storage/buffer/bufmgr.cTRACE_POSTGRESQL_BUFFER_CHECKPOINT_START(flags); // buffer检查点开始{ -- 遍历BUFFER区,将头信息need checkpoint的块刷入磁盘BufferSync(flags) // 与第一个trace之间包含遍历整个buffer区,增加脏块头信息need checkpointTRACE_POSTGRESQL_BUFFER_SYNC_START(NBuffers, num_to_write); // 开始sync buffer{ -- sync单个bufferSyncOneBufferFlushBufferTRACE_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);
含义请参考
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 50000000update 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 10000000progress: 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.434progress: 260.0 s, 41028.6 tps, lat 0.631 ms stddev 0.512progress: 265.0 s, 39556.4 tps, lat 0.655 ms stddev 0.631progress: 270.0 s, 19495.2 tps, lat 1.331 ms stddev 2.350progress: 275.0 s, 31672.6 tps, lat 0.818 ms stddev 0.915progress: 280.0 s, 38465.6 tps, lat 0.674 ms stddev 0.656progress: 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: 153863buffer__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秒。
[参考]
4. src/backend/utils/probes.d
5. src/backend/utils/probes.h