Re: could not read block 0 in file : read only 0 of 8192 bytes when doing nasty on immutable index function

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_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: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