Re: [HACKERS] WAL logging problem in 9.4.3?

Kyotaro Horiguchi <horikyota.ntt@gmail.com>

From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
To: noah@leadboat.com
Cc: robertmhaas@gmail.com, pgsql-hackers@postgresql.org, 9erthalion6@gmail.com, andrew.dunstan@2ndquadrant.com, hlinnaka@iki.fi, michael@paquier.xyz
Date: 2019-11-20T06:05:46Z
Lists: pgsql-hackers

Attachments

I'm in the benchmarking week..

Thanks for reviewing!.

At Sun, 17 Nov 2019 20:54:34 -0800, Noah Misch <noah@leadboat.com> wrote in 
> On Tue, Nov 05, 2019 at 02:53:35PM -0800, Noah Misch wrote:
> > I started pre-commit editing on 2019-10-28, and comment+README updates have
> > been the largest part of that.  I'll check my edits against the things you
> > list here, and I'll share on-list before committing.  I've now marked the CF
> > entry Ready for Committer.

I'll look into that soon.

By the way, before finalize this, I'd like to share the result of a
brief benchmarking.

First, I measured the direct effect of WAL skipping.
I measured the time required to do the following sequence for the
COMMIT-FPW-WAL case and COMMIT-fsync case. WAL and heap files are on
non-server spec HDD.

  BEGIN;
  TRUNCATE t;
  INSERT INTO t (SELECT a FROM generate_series(1, n) a);
  COMMIT;

REPLICA means the time with wal_level = replica
SYNC    means the time with wal_level = minimal and force file sync.
WAL     means the time with wal_level = minimal and force commit-WAL.
pages is the number of pages of the table.
(REPLICA comes from run.sh 1, SYNC/WAL comes from run.sh 2)

pages REPLICA    SYNC      WAL
    1:   144 ms   683 ms   217 ms
    3:   303 ms   995 ms   385 ms
    5:   271 ms  1007 ms   217 ms
   10:   157 ms  1043 ms   224 ms
   17:   189 ms  1007 ms   193 ms
   31:   202 ms  1091 ms   230 ms
   56:   265 ms  1175 ms   226 ms
  100:   510 ms  1307 ms   270 ms
  177:   790 ms  1523 ms   524 ms
  316:  1827 ms  1643 ms   719 ms
  562:  1904 ms  2109 ms  1148 ms
 1000:  3060 ms  2979 ms  2113 ms
 1778:  6077 ms  3945 ms  3618 ms
 3162: 13038 ms  7078 ms  6734 ms

There was a crossing point around 3000 pages. (bench1() finds that by
bisecting, run.sh 3).


With multiple sessions, the crossing point  but does not go so
small.

10 processes (run.pl 4 10) The numbers in parentheses are WAL[n]/WAL[n-1].
pages    SYNC     WAL
  316:  8436 ms  4694 ms
  562: 12067 ms  9627 ms (x2.1) # WAL wins
 1000: 19154 ms 43262 ms (x4.5) # SYNC wins. WAL's slope becomes steep.
 1778: 32495 ms 63863 ms (x1.4)

100 processes (run.pl 4 100)
pages    SYNC     WAL
   10: 13275 ms  1868 ms 
   17: 15919 ms  4438 ms (x2.3)
   31: 17063 ms  6431 ms (x1.5)
   56: 23193 ms 14276 ms (x2.2)  # WAL wins
  100: 35220 ms 67843 ms (x4.8)  # SYNC wins. WAL's slope becomes steep.

With 10 pgbench sessions.
pages   SYNC     WAL     
    1:   915 ms   301 ms
    3:  1634 ms   508 ms
    5:  1634 ms   293ms
   10:  1671 ms  1043 ms
   17:  1600 ms   333 ms
   31:  1864 ms   314 ms
   56:  1562 ms   448 ms
  100:  1538 ms   394 ms
  177:  1697 ms  1047 ms
  316:  3074 ms  1788 ms
  562:  3306 ms  1245 ms
 1000:  3440 ms  2182 ms
 1778:  5064 ms  6464 ms  # WAL's slope becomes steep
 3162:  8675 ms  8165 ms


I don't think the result of 100 processes is meaningful, so excluding
the result a candidate for wal_skip_threshold can be 1000.

Thoughts? The attached is the benchmark script.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

Commits

  1. Add perl2host call missing from a new test file.

  2. Skip WAL for new relfilenodes, under wal_level=minimal.

  3. Revert "Skip WAL for new relfilenodes, under wal_level=minimal."

  4. Back-patch log_newpage_range().

  5. During heap rebuild, lock any TOAST index until end of transaction.

  6. In log_newpage_range(), heed forkNum and page_std arguments.

  7. Back-patch src/test/recovery and PostgresNode from 9.6 to 9.5.

  8. Reduce pg_ctl's reaction time when waiting for postmaster start/stop.

  9. Accelerate end-of-transaction dropping of relations

  10. Redesign the planner's handling of index-descent cost estimation.

  11. Make TRUNCATE do truncate-in-place when processing a relation that was created