Re: pg_stat_statements issue with parallel maintenance (Was Re: WAL usage calculation patch)

On Tue, 7 Apr 2020 at 18:29, Masahiko Sawada
<masahiko.sawada@2ndquadrant.com> wrote:
>
> On Tue, 7 Apr 2020 at 17:42, Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Tue, Apr 7, 2020 at 1:30 PM Masahiko Sawada
> > <masahiko.sawada@2ndquadrant.com> wrote:
> > >
> > > Buffer usage statistics seem correct. The small differences would be
> > > catalog lookups Peter mentioned.
> > >
> >
> > Agreed, but can you check which part of code does that lookup?  I want
> > to see if we can avoid that from buffer usage stats or at least write
> > a comment about it, otherwise, we might have to face this question
> > again and again.
>
> Okay, I'll check it.
>

I've checked the buffer usage differences when parallel btree index creation.

TL;DR;

During tuple sorting individual parallel workers read blocks of
pg_amproc and pg_amproc_fam_proc_index to get the sort support
function. The call flow is like:

ParallelWorkerMain()
  _bt_parallel_scan_and_sort()
    tuplesort_begin_index_btree()
      PrepareSortSupportFromIndexRel()
        FinishSortSupportFunction()
          get_opfamily_proc()

The details are as follows.

I populated the test table by the following scripts:

create table test (c int) with (autovacuum_enabled = off, parallel_workers = 8);
insert into test select generate_series(1,10000000);

and create index DDL is:

create index test_idx on test (c);

Before executing the test script, I've put code at the following 4
places which checks the buffer usage at that point, and calculated the
difference between points: (a), (b) and (c). For example, (b) shows
the number of blocks read or hit during executing scanning heap and
building index.

1. Before executing CREATE INDEX command (at pgss_ProcessUtility())
(a)
2. Before parallel create index (at _bt_begin_parallel())
(b)
3. After parallel create index, after accumlating workers stats (at
_bt_end_parallel())
(c)
4. After executing CREATE INDEX command (at pgss_ProcessUtility())

And here is the results:

2 workers:
(a) hit: 107, read: 26
(b) hit: 12(=6+3+3), read: 44248(=15538+14453+14527)
(c) hit: 13, read: 2
total hit: 132, read:44276

4 workers:
(a) hit: 107, read: 26
(b) hit: 18(=6+3+3+3+3), read: 44248(=9368+8582+8544+9250+8504)
(c) hit: 13, read: 2
total hit: 138, read:44276

The table 'test' has 44276 blocks.

From the above results, the total number of reading blocks (44248
blocks) during parallel index creation is stable and equals to the
number of blocks of the test table. And we can see that extra three
blocks are read per workers. These three blocks are two for
pg_amproc_fam_proc_index and one for pg_amproc. That is, individual
parallel workers accesses these relations to get the sort support
function. The full backtrace is:

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff779c561a libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010cc9f90d postgres`pg_usleep(microsec=20000000)
at pgsleep.c:56:10
    frame #2: 0x000000010ca5a668
postgres`ReadBuffer_common(smgr=0x00007fe872848f70,
relpersistence='p', forkNum=MAIN_FORKNUM, blockNum=3, mode=RBM_NORMAL,
strategy=0x0000000000000000, hit=0x00007ffee363071b) at bufmgr.c:685:3
    frame #3: 0x000000010ca5a4b6
postgres`ReadBufferExtended(reln=0x000000010d58f790,
forkNum=MAIN_FORKNUM, blockNum=3, mode=RBM_NORMAL,
strategy=0x0000000000000000) at bufmgr.c:628:8
    frame #4: 0x000000010ca5a397
postgres`ReadBuffer(reln=0x000000010d58f790, blockNum=3) at
bufmgr.c:560:9
    frame #5: 0x000000010c67187e
postgres`_bt_getbuf(rel=0x000000010d58f790, blkno=3, access=1) at
nbtpage.c:792:9
    frame #6: 0x000000010c670507
postgres`_bt_getroot(rel=0x000000010d58f790, access=1) at
nbtpage.c:294:13
    frame #7: 0x000000010c679393
postgres`_bt_search(rel=0x000000010d58f790, key=0x00007ffee36312d0,
bufP=0x00007ffee3631bec, access=1, snapshot=0x00007fe8728388e0) at
nbtsearch.c:107:10
    frame #8: 0x000000010c67b489
postgres`_bt_first(scan=0x00007fe86f814998, dir=ForwardScanDirection)
at nbtsearch.c:1355:10
    frame #9: 0x000000010c676869
postgres`btgettuple(scan=0x00007fe86f814998, dir=ForwardScanDirection)
at nbtree.c:253:10
    frame #10: 0x000000010c6656ad
postgres`index_getnext_tid(scan=0x00007fe86f814998,
direction=ForwardScanDirection) at indexam.c:530:10
    frame #11: 0x000000010c66585b
postgres`index_getnext_slot(scan=0x00007fe86f814998,
direction=ForwardScanDirection, slot=0x00007fe86f814880) at
indexam.c:622:10
    frame #12: 0x000000010c663eac
postgres`systable_getnext(sysscan=0x00007fe86f814828) at genam.c:454:7
    frame #13: 0x000000010cc0be41
postgres`SearchCatCacheMiss(cache=0x00007fe872818e80, nkeys=4,
hashValue=3052139574, hashIndex=6, v1=1976, v2=23, v3=23, v4=2) at
catcache.c:1368:9
    frame #14: 0x000000010cc0bced
postgres`SearchCatCacheInternal(cache=0x00007fe872818e80, nkeys=4,
v1=1976, v2=23, v3=23, v4=2) at catcache.c:1299:9
    frame #15: 0x000000010cc0baa8
postgres`SearchCatCache4(cache=0x00007fe872818e80, v1=1976, v2=23,
v3=23, v4=2) at catcache.c:1191:9
    frame #16: 0x000000010cc27c82 postgres`SearchSysCache4(cacheId=5,
key1=1976, key2=23, key3=23, key4=2) at syscache.c:1156:9
    frame #17: 0x000000010cc105dd
postgres`get_opfamily_proc(opfamily=1976, lefttype=23, righttype=23,
procnum=2) at lsyscache.c:751:7
    frame #18: 0x000000010cc72e1d
postgres`FinishSortSupportFunction(opfamily=1976, opcintype=23,
ssup=0x00007fe86f8147d0) at sortsupport.c:99:24
    frame #19: 0x000000010cc73100
postgres`PrepareSortSupportFromIndexRel(indexRel=0x000000010d5ced48,
strategy=1, ssup=0x00007fe86f8147d0) at sortsupport.c:176:2
    frame #20: 0x000000010cc75463
postgres`tuplesort_begin_index_btree(heapRel=0x000000010d5cf808,
indexRel=0x000000010d5ced48, enforceUnique=false, workMem=21845,
coordinate=0x00007fe872839248, randomAccess=false) at
tuplesort.c:1114:3
    frame #21: 0x000000010c681ffc
postgres`_bt_parallel_scan_and_sort(btspool=0x00007fe872839738,
btspool2=0x0000000000000000, btshared=0x000000010d56c4c0,
sharedsort=0x000000010d56c460, sharedsort2=0x0000000000000000,
sortmem=21845, progress=false) at nbtsort.c:1941:23
    frame #22: 0x000000010c681eb2
postgres`_bt_parallel_build_main(seg=0x00007fe87280a058,
toc=0x000000010d56c000) at nbtsort.c:1889:2
    frame #23: 0x000000010c6b7358
postgres`ParallelWorkerMain(main_arg=1169089032) at parallel.c:1471:2
    frame #24: 0x000000010c9da86f postgres`StartBackgroundWorker at
bgworker.c:813:2
    frame #25: 0x000000010c9efbc0
postgres`do_start_bgworker(rw=0x00007fe86f419290) at
postmaster.c:5852:4
    frame #26: 0x000000010c9eff9f postgres`maybe_start_bgworkers at
postmaster.c:6078:9
    frame #27: 0x000000010c9eee99
postgres`sigusr1_handler(postgres_signal_arg=30) at
postmaster.c:5247:3
    frame #28: 0x00007fff77a74b5d libsystem_platform.dylib`_sigtramp + 29
    frame #29: 0x00007fff779c561b libsystem_kernel.dylib`__select + 11
    frame #30: 0x000000010c9ea48c postgres`ServerLoop at postmaster.c:1691:13
    frame #31: 0x000000010c9e9e06 postgres`PostmasterMain(argc=5,
argv=0x00007fe86f4036f0) at postmaster.c:1400:11
    frame #32: 0x000000010c8ee399 postgres`main(argc=<unavailable>,
argv=<unavailable>) at main.c:210:3
    frame #33: 0x00007fff778893d5 libdyld.dylib`start + 1

Regards,

--
Masahiko Sawada            http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services