PostgreSQL Why checkpointer impact performance so much ? - 4

来源：互联网发布：seo在线培训机构编辑：程序博客网时间：2024/05/23 15:13

Postgres2015全国用户大会将于11月20至21日在北京丽亭华苑酒店召开。本次大会嘉宾阵容强大，国内顶级PostgreSQL数据库专家将悉数到场，并特邀欧洲、俄罗斯、日本、美国等国家和地区的数据库方面专家助阵:

Postgres-XC项目的发起人铃木市一(SUZUKI Koichi)
Postgres-XL的项目发起人Mason Sharp
pgpool的作者石井达夫(Tatsuo Ishii)
PG-Strom的作者海外浩平(Kaigai Kohei)
Greenplum研发总监姚延栋
周正中(德哥), PostgreSQL中国用户会创始人之一
汪洋，平安科技数据库技术部经理
……

2015年度PG大象会报名地址：http://postgres2015.eventdove.com/
PostgreSQL中国社区： http://postgres.cn/
PostgreSQL专业1群： 3336901（已满）
PostgreSQL专业2群： 100910388
PostgreSQL专业3群： 150657323

这一篇主要谈一下和检查点相关的几个跟踪。

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

0 0