gist index builds try to open FSM over and over

Hi,

I built a gist index to try to test a theory in some other thread. For that
the indexes need to cover a lot of entries. With gist creating the index took
a long time, which made me strace the index build process.

Which lead me to notice this:

...
openat(AT_FDCWD, "base/16462/17747_fsm", O_RDWR|O_CLOEXEC) = -1 ENOENT (No such file or directory)
lseek(56, 0, SEEK_END)                  = 40173568
pwrite64(56, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 40173568) = 8192
lseek(56, 0, SEEK_END)                  = 40181760
openat(AT_FDCWD, "base/16462/17747_fsm", O_RDWR|O_CLOEXEC) = -1 ENOENT (No such file or directory)
lseek(56, 0, SEEK_END)                  = 40181760
pwrite64(56, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 40181760) = 8192
lseek(56, 0, SEEK_END)                  = 40189952
lseek(56, 0, SEEK_END)                  = 40189952
openat(AT_FDCWD, "base/16462/17747_fsm", O_RDWR|O_CLOEXEC) = -1 ENOENT (No such file or directory)
lseek(56, 0, SEEK_END)                  = 40189952
...

I.e. for every write we try and fail to open the FSM.

#0  __libc_open64 (file=0x30469c8 "base/16462/17747_fsm", oflag=524290) at ../sysdeps/unix/sysv/linux/open64.c:30
#1  0x0000000000cbe582 in BasicOpenFilePerm (fileName=0x30469c8 "base/16462/17747_fsm", fileFlags=524290,
fileMode=384)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/file/fd.c:1134
#2  0x0000000000cbf057 in PathNameOpenFilePerm (fileName=0x30469c8 "base/16462/17747_fsm", fileFlags=524290,
fileMode=384)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/file/fd.c:1620
#3  0x0000000000cbef88 in PathNameOpenFile (fileName=0x30469c8 "base/16462/17747_fsm", fileFlags=2)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/file/fd.c:1577
#4  0x0000000000cfeed2 in mdopenfork (reln=0x2fd5af8, forknum=FSM_FORKNUM, behavior=2)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/smgr/md.c:649
#5  0x0000000000cfe20b in mdexists (reln=0x2fd5af8, forknum=FSM_FORKNUM) at
../../../../../home/andres/src/postgresql/src/backend/storage/smgr/md.c:181
#6  0x0000000000d015b3 in smgrexists (reln=0x2fd5af8, forknum=FSM_FORKNUM) at
../../../../../home/andres/src/postgresql/src/backend/storage/smgr/smgr.c:400
#7  0x0000000000cc5078 in fsm_readbuf (rel=0x7f5b87977f38, addr=..., extend=false)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/freespace/freespace.c:571
#8  0x0000000000cc52d3 in fsm_search (rel=0x7f5b87977f38, min_cat=128 '\200')
    at ../../../../../home/andres/src/postgresql/src/backend/storage/freespace/freespace.c:690
#9  0x0000000000cc47a5 in GetPageWithFreeSpace (rel=0x7f5b87977f38, spaceNeeded=4096)
    at ../../../../../home/andres/src/postgresql/src/backend/storage/freespace/freespace.c:141
#10 0x0000000000cc5e52 in GetFreeIndexPage (rel=0x7f5b87977f38) at
../../../../../home/andres/src/postgresql/src/backend/storage/freespace/indexfsm.c:40
#11 0x0000000000855d4a in gistNewBuffer (r=0x7f5b87977f38, heaprel=0x7f5b87979688)
    at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gistutil.c:831
#12 0x0000000000844541 in gistplacetopage (rel=0x7f5b87977f38, freespace=819, giststate=0x2feae68, buffer=67261,
itup=0x7ffd3ce86c30,ntup=1, oldoffnum=0,
 
    newblkno=0x0, leftchildbuf=0, splitinfo=0x7ffd3ce86be0, markfollowright=true, heapRel=0x7f5b87979688,
is_build=true)
    at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gist.c:353
#13 0x0000000000846263 in gistinserttuples (state=0x7ffd3ce86c90, stack=0x2fde7e8, giststate=0x2feae68,
tuples=0x7ffd3ce86c30,ntup=1, oldoffnum=0,
 
    leftchild=0, rightchild=0, unlockbuf=false, unlockleftchild=false) at
../../../../../home/andres/src/postgresql/src/backend/access/gist/gist.c:1298
#14 0x00000000008461a7 in gistinserttuple (state=0x7ffd3ce86c90, stack=0x2fde7e8, giststate=0x2feae68, tuple=0x2fde708,
oldoffnum=0)
    at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gist.c:1251
#15 0x0000000000845681 in gistdoinsert (r=0x7f5b87977f38, itup=0x2fde708, freespace=819, giststate=0x2feae68,
heapRel=0x7f5b87979688,is_build=true)
 
    at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gist.c:887
#16 0x0000000000848c79 in gistBuildCallback (index=0x7f5b87977f38, tid=0x2f31f74, values=0x7ffd3ce87060,
isnull=0x7ffd3ce87040,tupleIsAlive=true,
 
    state=0x7ffd3ce87340) at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gistbuild.c:863
#17 0x000000000087d605 in heapam_index_build_range_scan (heapRelation=0x7f5b87979688, indexRelation=0x7f5b87977f38,
indexInfo=0x2fd9f50,allow_sync=true,
 
    anyvisible=false, progress=true, start_blockno=0, numblocks=4294967295, callback=0x848b6b <gistBuildCallback>,
callback_state=0x7ffd3ce87340,
    scan=0x2f31f18) at ../../../../../home/andres/src/postgresql/src/backend/access/heap/heapam_handler.c:1706
#18 0x0000000000847996 in table_index_build_scan (table_rel=0x7f5b87979688, index_rel=0x7f5b87977f38,
index_info=0x2fd9f50,allow_sync=true, progress=true,
 
    callback=0x848b6b <gistBuildCallback>, callback_state=0x7ffd3ce87340, scan=0x0)
    at ../../../../../home/andres/src/postgresql/src/include/access/tableam.h:1794
#19 0x0000000000847da8 in gistbuild (heap=0x7f5b87979688, index=0x7f5b87977f38, indexInfo=0x2fd9f50)
    at ../../../../../home/andres/src/postgresql/src/backend/access/gist/gistbuild.c:313
#20 0x000000000094c945 in index_build (heapRelation=0x7f5b87979688, indexRelation=0x7f5b87977f38, indexInfo=0x2fd9f50,
isreindex=false,parallel=true)
 
    at ../../../../../home/andres/src/postgresql/src/backend/catalog/index.c:3021
#21 0x000000000094970f in index_create (heapRelation=0x7f5b87979688, indexRelationName=0x2f2f798 "foo_i_idx1",
indexRelationId=17747,parentIndexRelid=0,
 
    parentConstraintId=0, relFileNumber=0, indexInfo=0x2fd9f50, indexColNames=0x2f2fc60, accessMethodId=783,
tableSpaceId=0,collationIds=0x2f32340,
 
    opclassIds=0x2f32358, opclassOptions=0x2f32370, coloptions=0x2f32388, stattargets=0x0, reloptions=0, flags=0,
constr_flags=0,
    allow_system_table_mods=false, is_internal=false, constraintId=0x7ffd3ce876f4)
    at ../../../../../home/andres/src/postgresql/src/backend/catalog/index.c:1275


The reason we reopen over and over is that we close the file in mdexist():

    /*
     * Close it first, to ensure that we notice if the fork has been unlinked
     * since we opened it.  As an optimization, we can skip that in recovery,
     * which already closes relations when dropping them.
     */
    if (!InRecovery)
        mdclose(reln, forknum);

We call smgrexists as part of this code:

static Buffer
fsm_readbuf(Relation rel, FSMAddress addr, bool extend)
...
    /*
     * If we haven't cached the size of the FSM yet, check it first.  Also
     * recheck if the requested block seems to be past end, since our cached
     * value might be stale.  (We send smgr inval messages on truncation, but
     * not on extension.)
     */
    if (reln->smgr_cached_nblocks[FSM_FORKNUM] == InvalidBlockNumber ||
        blkno >= reln->smgr_cached_nblocks[FSM_FORKNUM])
    {
        /* Invalidate the cache so smgrnblocks asks the kernel. */
        reln->smgr_cached_nblocks[FSM_FORKNUM] = InvalidBlockNumber;
        if (smgrexists(reln, FSM_FORKNUM))
            smgrnblocks(reln, FSM_FORKNUM);
        else
            reln->smgr_cached_nblocks[FSM_FORKNUM] = 0;
    }

Because we set the size to 0 if the the fork doesn't exist, we'll reenter
during the next call, and then do the same thing again.


I don't think this is a huge performance issue or anything, but somehow it
seems indicative of something being "wrong".

It seems likely we encounter this issue not just with gist, but I haven't
checked yet.

Greetings,

Andres Freund