Re: could not read block 0 in file : read only 0 of 8192 bytes whendoing nasty on immutable index function - Mailing list pgsql-bugs

Hi,

Luca, it'd be cool if you could not top-quote on this list - Thanks!

Others - this seems like a potentially more longstanding bug, see the
bottom of the mail.

Peter, looks like you might be involved specifically.


On 2018-06-28 08:26:58 +0200, Luca Ferrari wrote:
> Got it: it happens if you drop and recreate the index. It shows up
> either setting max_parallel_maintanance_workers to zero or a greater
> value.
> testdb=> create table t( pk serial, t text );
> CREATE TABLE
> testdb=> insert into t( t ) values( 'hello' ), ('world');
> INSERT 0 2
> testdb=> create or replace function f_fake( i int )
> returns text
> as $body$
> declare
>   v_t text;
> begin
>    select t into strict v_t
>    from t where pk = i limit 1;
>    return v_t;
> exception
>   when no_data_found then return 'a';
> end
> $body$
> language plpgsql immutable;
> CREATE FUNCTION
> testdb=> create index idx_fake on t ( f_fake( pk ) );
> CREATE INDEX
> testdb=> drop index idx_fake;
> DROP INDEX
>
> testdb=> create index idx_fake on t ( f_fake( pk ) );
> 2018-06-28 10:23:18.275 CEST [892] ERROR:  could not read block 0 in
> file "base/16392/16538": read only 0 of 8192 bytes
> 2018-06-28 10:23:18.275 CEST [892] CONTEXT:  SQL statement "select t
>                  from t where pk = i limit 1"
>         PL/pgSQL function f_fake(integer) line 5 at SQL statement
> 2018-06-28 10:23:18.275 CEST [892] STATEMENT:  create index idx_fake
> on t ( f_fake( pk ) );
> ERROR:  could not read block 0 in file "base/16392/16538": read only 0
> of 8192 bytes
> CONTEXT:  SQL statement "select t                    from t where pk =
> i limit 1"
> PL/pgSQL function f_fake(integer) line 5 at SQL statement

The backtrace for the error is:

#0  mdread (reln=0x55c314f5e580, forknum=MAIN_FORKNUM, blocknum=0, buffer=0x7f010eaa8b80 "") at
/home/andres/src/postgresql/src/backend/storage/smgr/md.c:785
#1  0x000055c31416d8aa in smgrread (reln=0x55c314f5e580, forknum=MAIN_FORKNUM, blocknum=0, buffer=0x7f010eaa8b80 "")
    at /home/andres/src/postgresql/src/backend/storage/smgr/smgr.c:628
#2  0x000055c31412cfb3 in ReadBuffer_common (smgr=0x55c314f5e580, relpersistence=112 'p', forkNum=MAIN_FORKNUM,
blockNum=0,mode=RBM_NORMAL, strategy=0x0,
 
    hit=0x7ffe19a7e8eb) at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:890
#3  0x000055c31412c8d6 in ReadBufferExtended (reln=0x7f0111a552f0, forkNum=MAIN_FORKNUM, blockNum=0, mode=RBM_NORMAL,
strategy=0x0)
    at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:664
#4  0x000055c31412c7b3 in ReadBuffer (reln=0x7f0111a552f0, blockNum=0) at
/home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:596
#5  0x000055c313db47c8 in _bt_getbuf (rel=0x7f0111a552f0, blkno=0, access=1) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:736
#6  0x000055c313db4297 in _bt_getrootheight (rel=0x7f0111a552f0) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:608
#7  0x000055c3140a3179 in get_relation_info (root=0x55c314f782a8, relationObjectId=121577, inhparent=false,
rel=0x55c314f78bd0)
    at /home/andres/src/postgresql/src/backend/optimizer/util/plancat.c:412
#8  0x000055c3140a8894 in build_simple_rel (root=0x55c314f782a8, relid=1, parent=0x0) at
/home/andres/src/postgresql/src/backend/optimizer/util/relnode.c:221
#9  0x000055c31406e183 in add_base_rels_to_query (root=0x55c314f782a8, jtnode=0x55c314f77e40)
    at /home/andres/src/postgresql/src/backend/optimizer/plan/initsplan.c:113
#10 0x000055c31406e1c9 in add_base_rels_to_query (root=0x55c314f782a8, jtnode=0x55c314f77da8)
    at /home/andres/src/postgresql/src/backend/optimizer/plan/initsplan.c:121
#11 0x000055c314072b33 in query_planner (root=0x55c314f782a8, tlist=0x55c314f78798, qp_callback=0x55c31407874b
<standard_qp_callback>,
    qp_extra=0x7ffe19a7ec40) at /home/andres/src/postgresql/src/backend/optimizer/plan/planmain.c:144
#12 0x000055c314075cb7 in grouping_planner (root=0x55c314f782a8, inheritance_update=false, tuple_fraction=1)
    at /home/andres/src/postgresql/src/backend/optimizer/plan/planner.c:1901
#13 0x000055c3140743c6 in subquery_planner (glob=0x55c314f78210, parse=0x55c314f77988, parent_root=0x0,
hasRecursion=false,tuple_fraction=0)
 
    at /home/andres/src/postgresql/src/backend/optimizer/plan/planner.c:966
#14 0x000055c3140730a1 in standard_planner (parse=0x55c314f77988, cursorOptions=256, boundParams=0x55c314f76620)
    at /home/andres/src/postgresql/src/backend/optimizer/plan/planner.c:405
#15 0x000055c314072e3a in planner (parse=0x55c314f77988, cursorOptions=256, boundParams=0x55c314f76620)
    at /home/andres/src/postgresql/src/backend/optimizer/plan/planner.c:263
#16 0x000055c31416ffeb in pg_plan_query (querytree=0x55c314f77988, cursorOptions=256, boundParams=0x55c314f76620)
    at /home/andres/src/postgresql/src/backend/tcop/postgres.c:809
#17 0x000055c31417011e in pg_plan_queries (querytrees=0x55c314f77928, cursorOptions=256, boundParams=0x55c314f76620)
    at /home/andres/src/postgresql/src/backend/tcop/postgres.c:875
#18 0x000055c3142c6a9e in BuildCachedPlan (plansource=0x55c314f8f9a8, qlist=0x55c314f77928, boundParams=0x55c314f76620,
queryEnv=0x0)
    at /home/andres/src/postgresql/src/backend/utils/cache/plancache.c:938
#19 0x000055c3142c70af in GetCachedPlan (plansource=0x55c314f8f9a8, boundParams=0x55c314f76620, useResOwner=true,
queryEnv=0x0)
    at /home/andres/src/postgresql/src/backend/utils/cache/plancache.c:1213
#20 0x000055c313fd6cbf in _SPI_execute_plan (plan=0x55c314f97a28, paramLI=0x55c314f76620, snapshot=0x0,
crosscheck_snapshot=0x0,read_only=true,
 
    fire_triggers=true, tcount=2) at /home/andres/src/postgresql/src/backend/executor/spi.c:2122
#21 0x000055c313fd3f88 in SPI_execute_plan_with_paramlist (plan=0x55c314f97a28, params=0x55c314f76620, read_only=true,
tcount=2)
    at /home/andres/src/postgresql/src/backend/executor/spi.c:481
#22 0x00007f010e5df915 in exec_stmt_execsql (estate=0x7ffe19a7f570, stmt=0x55c314f7bf48) at
/home/andres/src/postgresql/src/pl/plpgsql/src/pl_exec.c:4062
#23 0x00007f010e5db424 in exec_stmt (estate=0x7ffe19a7f570, stmt=0x55c314f7bf48) at
/home/andres/src/postgresql/src/pl/plpgsql/src/pl_exec.c:1984
#24 0x00007f010e5db126 in exec_stmts (estate=0x7ffe19a7f570, stmts=0x55c314f7bfa8) at
/home/andres/src/postgresql/src/pl/plpgsql/src/pl_exec.c:1875
#25 0x00007f010e5dac0a in exec_stmt_block (estate=0x7ffe19a7f570, block=0x55c314f7c5f8) at
/home/andres/src/postgresql/src/pl/plpgsql/src/pl_exec.c:1667
#26 0x00007f010e5d8bfc in plpgsql_exec_function (func=0x55c314ec8da8, fcinfo=0x55c314f6c1f0, simple_eval_estate=0x0,
atomic=true)
    at /home/andres/src/postgresql/src/pl/plpgsql/src/pl_exec.c:586
#27 0x00007f010e5d353a in plpgsql_call_handler (fcinfo=0x55c314f6c1f0) at
/home/andres/src/postgresql/src/pl/plpgsql/src/pl_handler.c:263
#28 0x000055c313f7f5af in ExecInterpExpr (state=0x55c314f6bce8, econtext=0x55c314f6bae0, isnull=0x7ffe19a7faa3)
    at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:654
#29 0x000055c313f811bd in ExecInterpExprStillValid (state=0x55c314f6bce8, econtext=0x55c314f6bae0,
isNull=0x7ffe19a7faa3)
    at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:1786
#30 0x000055c313e29369 in ExecEvalExprSwitchContext (state=0x55c314f6bce8, econtext=0x55c314f6bae0,
isNull=0x7ffe19a7faa3)
    at /home/andres/src/postgresql/src/include/executor/executor.h:303
#31 0x000055c313e2c42f in FormIndexDatum (indexInfo=0x55c314f2cd20, slot=0x55c314eba798, estate=0x55c314f6b8c8,
values=0x7ffe19a7fd90,isnull=0x7ffe19a7fd70)
 
    at /home/andres/src/postgresql/src/backend/catalog/index.c:2041
#32 0x000055c313e2d756 in IndexBuildHeapRangeScan (heapRelation=0x7f0111a4cc10, indexRelation=0x7f0111a552f0,
indexInfo=0x55c314f2cd20,allow_sync=true,
 
    anyvisible=false, start_blockno=0, numblocks=4294967295, callback=0x55c313dc3547 <_bt_build_callback>,
callback_state=0x7ffe19a80010,scan=0x55c314f5a188)
 
    at /home/andres/src/postgresql/src/backend/catalog/index.c:2876
#33 0x000055c313e2cd72 in IndexBuildHeapScan (heapRelation=0x7f0111a4cc10, indexRelation=0x7f0111a552f0,
indexInfo=0x55c314f2cd20,allow_sync=true, 
    callback=0x55c313dc3547 <_bt_build_callback>, callback_state=0x7ffe19a80010, scan=0x0) at
/home/andres/src/postgresql/src/backend/catalog/index.c:2426
#34 0x000055c313dc33b6 in _bt_spools_heapscan (heap=0x7f0111a4cc10, index=0x7f0111a552f0, buildstate=0x7ffe19a80010,
indexInfo=0x55c314f2cd20)
    at /home/andres/src/postgresql/src/backend/access/nbtree/nbtsort.c:472
#35 0x000055c313dc310b in btbuild (heap=0x7f0111a4cc10, index=0x7f0111a552f0, indexInfo=0x55c314f2cd20)
    at /home/andres/src/postgresql/src/backend/access/nbtree/nbtsort.c:324
#36 0x000055c313e2c9bd in index_build (heapRelation=0x7f0111a4cc10, indexRelation=0x7f0111a552f0,
indexInfo=0x55c314f2cd20,isprimary=false, isreindex=false,
 
    parallel=true) at /home/andres/src/postgresql/src/backend/catalog/index.c:2288
#37 0x000055c313e2b030 in index_create (heapRelation=0x7f0111a4cc10, indexRelationName=0x55c314eba040 "idx_fake",
indexRelationId=121588,parentIndexRelid=0,
 
    parentConstraintId=0, relFileNode=0, indexInfo=0x55c314f2cd20, indexColNames=0x55c314ec46d0,
accessMethodObjectId=403,tableSpaceId=0,
 
    collationObjectId=0x55c314ec4b40, classObjectId=0x55c314ec4b60, coloptions=0x55c314ec4b80, reloptions=0, flags=0,
constr_flags=0,
    allow_system_table_mods=false, is_internal=false, constraintId=0x7ffe19a802a0) at
/home/andres/src/postgresql/src/backend/catalog/index.c:1187
#38 0x000055c313f11303 in DefineIndex (relationId=121577, stmt=0x55c314f2d048, indexRelationId=0, parentIndexId=0,
parentConstraintId=0,
    is_alter_table=false, check_rights=true, check_not_in_use=true, skip_build=false, quiet=false)
    at /home/andres/src/postgresql/src/backend/commands/indexcmds.c:850
#39 0x000055c314179d92 in ProcessUtilitySlow (pstate=0x55c314eb9d68, pstmt=0x55c314e9a3b8,
    queryString=0x55c314e994d8 "create index idx_fake on t ( f_fake( pk ) );", context=PROCESS_UTILITY_TOPLEVEL,
params=0x0,queryEnv=0x0,
 
    dest=0x55c314e9a6a8, completionTag=0x7ffe19a80b80 "") at
/home/andres/src/postgresql/src/backend/tcop/utility.c:1352
#40 0x000055c314178f44 in standard_ProcessUtility (pstmt=0x55c314e9a3b8, queryString=0x55c314e994d8 "create index
idx_fakeon t ( f_fake( pk ) );",
 
    context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x55c314e9a6a8, completionTag=0x7ffe19a80b80 "")
    at /home/andres/src/postgresql/src/backend/tcop/utility.c:920
#41 0x000055c31417803c in ProcessUtility (pstmt=0x55c314e9a3b8, queryString=0x55c314e994d8 "create index idx_fake on t
(f_fake( pk ) );",
 
    context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x55c314e9a6a8, completionTag=0x7ffe19a80b80 "")
    at /home/andres/src/postgresql/src/backend/tcop/utility.c:360
#42 0x000055c314176fe8 in PortalRunUtility (portal=0x55c314f01098, pstmt=0x55c314e9a3b8, isTopLevel=true,
setHoldSnapshot=false,dest=0x55c314e9a6a8,
 
    completionTag=0x7ffe19a80b80 "") at /home/andres/src/postgresql/src/backend/tcop/pquery.c:1178
#43 0x000055c314177208 in PortalRunMulti (portal=0x55c314f01098, isTopLevel=true, setHoldSnapshot=false,
dest=0x55c314e9a6a8,altdest=0x55c314e9a6a8,
 
    completionTag=0x7ffe19a80b80 "") at /home/andres/src/postgresql/src/backend/tcop/pquery.c:1324
#44 0x000055c314176736 in PortalRun (portal=0x55c314f01098, count=9223372036854775807, isTopLevel=true, run_once=true,
dest=0x55c314e9a6a8,
    altdest=0x55c314e9a6a8, completionTag=0x7ffe19a80b80 "") at
/home/andres/src/postgresql/src/backend/tcop/pquery.c:799
#45 0x000055c314170560 in exec_simple_query (query_string=0x55c314e994d8 "create index idx_fake on t ( f_fake( pk )
);")
    at /home/andres/src/postgresql/src/backend/tcop/postgres.c:1122
#46 0x000055c314174914 in PostgresMain (argc=1, argv=0x55c314ec7720, dbname=0x55c314ec7580 "postgres",
username=0x55c314e95bc8"andres")
 
    at /home/andres/src/postgresql/src/backend/tcop/postgres.c:4153
#47 0x000055c3140d0e3c in BackendRun (port=0x55c314ebc5a0) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4361
#48 0x000055c3140d0579 in BackendStartup (port=0x55c314ebc5a0) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4033
#49 0x000055c3140cc985 in ServerLoop () at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1706
#50 0x000055c3140cc1d4 in PostmasterMain (argc=49, argv=0x55c314e93330) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1379
#51 0x000055c313ff523f in main (argc=49, argv=0x55c314e93330) at
/home/andres/src/postgresql/src/backend/main/main.c:228


What you're seeing here is just a consequence of doing nasty things in
your index function - you're accessing the index inside the function
used to build the index.  That fails because the index isn't actually
built at that point.  It's possible we could find a way to report a
better error, but I don't think we'll try to make this actually work.


> testdb=> select * from t;
> 2018-06-28 10:23:23.642 CEST [892] ERROR:  could not open relation
> with OID 16538
> 2018-06-28 10:23:23.642 CEST [892] STATEMENT:  select * from t;
> ERROR:  could not open relation with OID 16538

This however seems wrong.  Cleary the relation's index list is out of
date.

I believe this happens because there's currently no relcache
invalidation registered for the main relation, until *after* the index
is built. Normally it'd be the CacheInvalidateRelcacheByTuple(tuple) in
index_update_stats(), which is called at the bottom of index_build().
But we never get there, because the earlier error.  That's bad, because
any relcache entry built *after* the CommandCounterIncrement() in
CommandCounterIncrement() will now be outdated.

In the olden days we most of the time didn't build a relcache entry
until after the index was built - but plan_create_index_workers() now
does. I'm suspect there's other ways to trigger that earlier, too.

Putting in a CacheInvalidateRelcache(heapRelation); before the CCI in
index_create() indeed makes the "borked relcache" problem go away.


I wonder why we don't just generally trigger invalidations to an
indexes' "owning" relation in CacheInvalidateHeapTuple()?
    else if (tupleRelId == IndexRelationId)
    {
        Form_pg_index indextup = (Form_pg_index) GETSTRUCT(tuple);

        /*
         * When a pg_index row is updated, we should send out a relcache inval
         * for the index relation.  As above, we don't know the shared status
         * of the index, but in practice it doesn't matter since indexes of
         * shared catalogs can't have such updates.
         */
        relationId = indextup->indexrelid;
        databaseId = MyDatabaseId;
    }


Greetings,

Andres Freund