Let PostgreSQL's On Schedule checkpoint write buffer smooth spread cycle by tuning IsCheckpointOnSchedule? - Mailing list pgsql-hackers

# stap -DMAXSKIPPED=100000 -v 11111 -e '

global s_var, e_var, stat_var;

/* probe smgr__md__read__start(ForkNumber, BlockNumber, Oid, Oid, Oid, int); */

probe process("/opt/pgsql/bin/postgres").mark("smgr__md__read__start") {

  s_var[pid(),1] = gettimeofday_us()

}

/* probe smgr__md__read__done(ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int); */

probe process("/opt/pgsql/bin/postgres").mark("smgr__md__read__done") {

  e_var[pid(),1] = gettimeofday_us()

  if ( s_var[pid(),1] > 0 )

    stat_var[pid(),1] <<< e_var[pid(),1] - s_var[pid(),1]

}

/* probe smgr__md__write__start(ForkNumber, BlockNumber, Oid, Oid, Oid, int); */

probe process("/opt/pgsql/bin/postgres").mark("smgr__md__write__start") {

  s_var[pid(),2] = gettimeofday_us()

}

/* probe smgr__md__write__done(ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int); */

probe process("/opt/pgsql/bin/postgres").mark("smgr__md__write__done") {

  e_var[pid(),2] = gettimeofday_us()

  if ( s_var[pid(),2] > 0 )

    stat_var[pid(),2] <<< e_var[pid(),2] - s_var[pid(),2]

}

probe process("/opt/pgsql/bin/postgres").mark("buffer__sync__start") {

  printf("buffer__sync__start num_buffers: %d, dirty_buffers: %d\n", $NBuffers, $num_to_write)

}

probe process("/opt/pgsql/bin/postgres").mark("checkpoint__start") {

  printf("checkpoint start\n")

}

probe process("/opt/pgsql/bin/postgres").mark("checkpoint__done") {

  printf("checkpoint done\n")

}

probe timer.s(1) {

  foreach ([v1,v2] in stat_var +) {

    if ( @count(stat_var[v1,v2]) >0 ) {

      printf("r1_or_w2 %d, pid: %d, min: %d, max: %d, avg: %d, sum: %d, count: %d\n", v2, v1, @min(stat_var[v1,v2]), @max(stat_var[v1,v2]), @avg(stat_var[v1,v2]), @sum(stat_var[v1,v2]), @count(stat_var[v1,v2]))

    }

  }

  printf("----------------------------------end-----------------------------\n")

  delete s_var

  delete e_var

  delete stat_var

}'

Use the test table and data:

create table tbl(id primary key,info text,crt_time timestamp);

insert into tbl select generate_series(1,50000000),now(),now();

Use pgbench test it.

$ vi test.sql

\setrandom id 1 50000000

update tbl set crt_time=now() where id = :id ;

$ pgbench -M prepared -n -r -f ./test.sql -P 1 -c 28 -j 28 -T 100000000

When on schedule checkpoint occure , the tps:

progress: 255.0 s, 58152.2 tps, lat 0.462 ms stddev 0.504

progress: 256.0 s, 31382.8 tps, lat 0.844 ms stddev 2.331

progress: 257.0 s, 14615.5 tps, lat 1.863 ms stddev 4.554

progress: 258.0 s, 16258.4 tps, lat 1.652 ms stddev 4.139

progress: 259.0 s, 17814.7 tps, lat 1.526 ms stddev 4.035

progress: 260.0 s, 14573.8 tps, lat 1.825 ms stddev 5.592

progress: 261.0 s, 16736.6 tps, lat 1.600 ms stddev 5.018

progress: 262.0 s, 19060.5 tps, lat 1.448 ms stddev 4.818

progress: 263.0 s, 20553.2 tps, lat 1.290 ms stddev 4.146

progress: 264.0 s, 26223.0 tps, lat 1.042 ms stddev 3.711

progress: 265.0 s, 31953.0 tps, lat 0.836 ms stddev 2.837

progress: 266.0 s, 43396.1 tps, lat 0.627 ms stddev 1.615

progress: 267.0 s, 50487.8 tps, lat 0.533 ms stddev 0.647

progress: 268.0 s, 53537.7 tps, lat 0.502 ms stddev 0.598

progress: 269.0 s, 54259.3 tps, lat 0.496 ms stddev 0.624

progress: 270.0 s, 56139.8 tps, lat 0.479 ms stddev 0.524

The parameters for onschedule checkpoint:

checkpoint_segments = 512

checkpoint_timeout = 5min

checkpoint_completion_target = 0.9

stap's output : 

there is 156467 dirty blocks, we can see the buffer write per second, write buffer is not smooth between time target.

but between xlog target.

156467/(4.5*60*0.9) = 579.5 write per second.

checkpoint start

buffer__sync__start num_buffers: 262144, dirty_buffers: 156467

r1_or_w2 2, pid: 19848, min: 41, max: 1471, avg: 49, sum: 425291, count: 8596

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 153, avg: 49, sum: 450597, count: 9078

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 643, avg: 51, sum: 429193, count: 8397

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 1042, avg: 55, sum: 449091, count: 8097

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 254, avg: 52, sum: 296668, count: 5617

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 39, max: 171, avg: 54, sum: 321027, count: 5851

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 138, avg: 60, sum: 300056, count: 4953

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 42, max: 1217, avg: 65, sum: 312859, count: 4748

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 1371, avg: 56, sum: 353905, count: 6304

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 41, max: 358, avg: 58, sum: 236254, count: 4038

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 34, max: 1239, avg: 63, sum: 296906, count: 4703

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 31, max: 17408, avg: 63, sum: 415234, count: 6534

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 31, max: 5486, avg: 57, sum: 190345, count: 3318

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 29, max: 510, avg: 53, sum: 136221, count: 2563

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 32, max: 733, avg: 52, sum: 108327, count: 2070

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 34, max: 382, avg: 53, sum: 96157, count: 1812

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 43, max: 327, avg: 53, sum: 83641, count: 1571

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 33, max: 102, avg: 54, sum: 79991, count: 1468

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 35, max: 88, avg: 53, sum: 74338, count: 1389

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 32, max: 86, avg: 52, sum: 65710, count: 1243

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 30, max: 347, avg: 52, sum: 66866, count: 1263

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 31, max: 93, avg: 54, sum: 75642, count: 1398

----------------------------------end-----------------------------

r1_or_w2 2, pid: 19848, min: 33, max: 100, avg: 51, sum: 62302, count: 1216

......

I think we can add an condition to the IsCheckpointOnSchedule, 

                if (synchronous_commit != SYNCHRONOUS_COMMIT_OFF)

                {

                    recptr = GetInsertRecPtr();

                    elapsed_xlogs = (((double) (recptr - ckpt_start_recptr)) / XLogSegSize) / CheckPointSegments;

                    if (progress < elapsed_xlogs)

                    {

                        ckpt_cached_elapsed = elapsed_xlogs;

                        return false;

                    }

                 }

# vi src/backend/postmaster/checkpointer.c

#include "access/xact.h"

/*

 * IsCheckpointOnSchedule -- are we on schedule to finish this checkpoint

 *               in time?

 *

 * Compares the current progress against the time/segments elapsed since last

 * checkpoint, and returns true if the progress we've made this far is greater

 * than the elapsed time/segments.

 */

static bool

IsCheckpointOnSchedule(double progress)

{

        XLogRecPtr      recptr;

        struct timeval now;

        double          elapsed_xlogs,

                                elapsed_time;

        Assert(ckpt_active);

        /* Scale progress according to checkpoint_completion_target. */

        progress *= CheckPointCompletionTarget;

        /*

         * Check against the cached value first. Only do the more expensive

         * calculations once we reach the target previously calculated. Since

         * neither time or WAL insert pointer moves backwards, a freshly

         * calculated value can only be greater than or equal to the cached value.

         */

        if (progress < ckpt_cached_elapsed)

                return false;

        /*

         * Check progress against WAL segments written and checkpoint_segments.

         *

         * We compare the current WAL insert location against the location

         * computed before calling CreateCheckPoint. The code in XLogInsert that

         * actually triggers a checkpoint when checkpoint_segments is exceeded

         * compares against RedoRecptr, so this is not completely accurate.

         * However, it's good enough for our purposes, we're only calculating an

         * estimate anyway.

         */

        if (!RecoveryInProgress())

        {

                if (synchronous_commit != SYNCHRONOUS_COMMIT_OFF)

                {

                    recptr = GetInsertRecPtr();

                    elapsed_xlogs = (((double) (recptr - ckpt_start_recptr)) / XLogSegSize) / CheckPointSegments;

                    if (progress < elapsed_xlogs)

                    {

                        ckpt_cached_elapsed = elapsed_xlogs;

                        return false;

                    }

                 }

        }

        /*

         * Check progress against time elapsed and checkpoint_timeout.

         */

        gettimeofday(&now, NULL);

        elapsed_time = ((double) ((pg_time_t) now.tv_sec - ckpt_start_time) +

                                        now.tv_usec / 1000000.0) / CheckPointTimeout;

        if (progress < elapsed_time)

        {

                ckpt_cached_elapsed = elapsed_time;

                return false;

        }

        /* It looks like we're on schedule. */

        return true;

}

# gmake && gmake install

$ pg_ctl restart -m fast

Test again:

progress: 291.0 s, 63144.9 tps, lat 0.426 ms stddev 0.383

progress: 292.0 s, 55063.7 tps, lat 0.480 ms stddev 1.433

progress: 293.0 s, 12225.3 tps, lat 2.238 ms stddev 4.460

progress: 294.0 s, 16436.4 tps, lat 1.621 ms stddev 4.043

progress: 295.0 s, 18516.5 tps, lat 1.444 ms stddev 3.286

progress: 296.0 s, 21983.7 tps, lat 1.251 ms stddev 2.941

progress: 297.0 s, 25759.7 tps, lat 1.034 ms stddev 2.356

progress: 298.0 s, 33139.4 tps, lat 0.821 ms stddev 1.676

progress: 299.0 s, 41904.9 tps, lat 0.644 ms stddev 1.134

progress: 300.0 s, 52432.9 tps, lat 0.513 ms stddev 0.470

progress: 301.0 s, 57115.4 tps, lat 0.471 ms stddev 0.325

progress: 302.0 s, 59422.1 tps, lat 0.452 ms stddev 0.297

progress: 303.0 s, 59860.5 tps, lat 0.449 ms stddev 0.309

We can see checkpointer wiriter buffer smooth(spread time perid) this time.

checkpoint start

----------------------------------end-----------------------------

buffer__sync__start num_buffers: 262144, dirty_buffers: 156761

r1_or_w2 2, pid: 22334, min: 51, max: 137, avg: 60, sum: 52016, count: 860

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 108, avg: 58, sum: 35526, count: 604

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 145, avg: 71, sum: 39779, count: 559

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 52, max: 172, avg: 79, sum: 47279, count: 594

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 44, max: 160, avg: 63, sum: 36907, count: 581

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 113, avg: 61, sum: 33895, count: 552

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 116, avg: 61, sum: 38177, count: 617

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 113, avg: 62, sum: 34199, count: 550

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 53, max: 109, avg: 65, sum: 39842, count: 606

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 50, max: 118, avg: 64, sum: 35099, count: 545

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 50, max: 107, avg: 64, sum: 39027, count: 606

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 51, max: 114, avg: 62, sum: 34054, count: 545

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 47, max: 106, avg: 63, sum: 38573, count: 605

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 48, max: 101, avg: 62, sum: 38051, count: 607

----------------------------------end-----------------------------

r1_or_w2 2, pid: 22334, min: 42, max: 103, avg: 61, sum: 33596, count: 545