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

I've found this strange (to me) behavior when doing nasty things with
indexes and immutable functions:

create table t( pk serial, t text );
insert into t( t ) values( 'hello' ), ('world');
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;

Of course, f_fake is not immutable.
When on 10.4 or 11 beta 1 I try to create an index on this nasty
crappy function:

create index idx_fake on t ( f_fake( pk ) );

ERROR: could not read block 0 in file "base/16392/16444": 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

that is somehow correct (because the function cannot be used to build
an index), but then it goes worst:

elect * from t;
ERROR: could not open relation with OID 16444

If I then disconnect and reconnect I'm able to issue the select and
get back the results. But if I issue a reindex I got the same error
and the table "becames unreadable" for the whole session.
On 10.3 the table is never locked for the session, that is I can
create the index, I can query the table and get the results, but I
cannot reindex. However, even after a reindex, it does allow me to
select data from the table.

So my question is: why this behavior in later PostgreSQL?

On Wed, Jun 27, 2018 at 11:35 AM, Luca Ferrari <fluca1978(at)gmail(dot)com> wrote:
> If I then disconnect and reconnect I'm able to issue the select and
> get back the results. But if I issue a reindex I got the same error
> and the table "becames unreadable" for the whole session.
> On 10.3 the table is never locked for the session, that is I can
> create the index, I can query the table and get the results, but I
> cannot reindex. However, even after a reindex, it does allow me to
> select data from the table.
>
> So my question is: why this behavior in later PostgreSQL?

It might have something to do with the changes to parallel CREATE
INDEX. It changed how we tracked whether or not an index could be used
because it was currently undergoing reindexing. This is supposed to
make no difference at all, but there was one bug that could cause us
to consider an index irrevocably unusable.

Do you find that the issue goes away if you set
max_parallel_maintenance_workers=0 on v11/master?

--
Peter Geoghegan

Hi,

On 2018-06-27 20:35:16 +0200, Luca Ferrari wrote:
> I've found this strange (to me) behavior when doing nasty things with
> indexes and immutable functions:
>
> create table t( pk serial, t text );
> insert into t( t ) values( 'hello' ), ('world');
> 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;
>
> Of course, f_fake is not immutable.
> When on 10.4 or 11 beta 1 I try to create an index on this nasty
> crappy function:
>
> create index idx_fake on t ( f_fake( pk ) );
>
> ERROR: could not read block 0 in file "base/16392/16444": 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

> that is somehow correct (because the function cannot be used to build
> an index), but then it goes worst:
>
> elect * from t;
> ERROR: could not open relation with OID 16444

That certainly isn't behaviour I'd expect. Doing nasty stuff inside an
immutable function will have bad consequences, but the permanent failure
shouldn't be there.

But I also can't reproduce it either on 10.4, 10-current, master. Did
you build from source? Packages? Any extensions? Is there anything
missing from the above instruction to reproduce this?

Greetings,

Andres Freund

On Wed, Jun 27, 2018 at 10:44 PM Andres Freund <andres(at)anarazel(dot)de> wrote:
> But I also can't reproduce it either on 10.4, 10-current, master. Did
> you build from source? Packages? Any extensions? Is there anything
> missing from the above instruction to reproduce this?

Somehow today I cannot reproduce it by myself, I must have missed
something since I cannot get locked out from the table.
However I've tested that on 10.3 (one I've at the moment):
1) create table, insert, create index, reindex causes the problem but
do not locks the further select
2) create table, create index, insert, reindex does not show the
problem (i.e., no comlain at all)

while on the following version both 1 and 2 shows the reading problem
once the reindex is issued (but allows further selects):
testdb=> select version();

version
---------------------------------------------------------------------------------------------------------------------------------------------------------
PostgreSQL 11beta1 on x86_64-unknown-freebsd11.1, compiled by FreeBSD
clang version 4.0.0 (tags/RELEASE_400/final 297347) (based on LLVM
4.0.0), 64-bit

It seems not to depend on max_parallel_maintance_workers.
Sorry, I cannot provide more help at the moment.
I will try to reproduce it again.

Luca

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

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 has been tested on

testdb=> select version();

version
---------------------------------------------------------------------------------------------------------------------------------------------------------
PostgreSQL 11beta1 on x86_64-unknown-freebsd11.1, compiled by FreeBSD
clang version 4.0.0 (tags/RELEASE_400/final 297347) (based on LLVM
4.0.0), 64-bit

testdb=> show max_parallel_maintenance_workers ;
max_parallel_maintenance_workers
----------------------------------
2

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

On Thu, Jun 28, 2018 at 8:02 AM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> Peter, looks like you might be involved specifically.

Seems that way.

> 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.

Note that there is a kludge within plan_create_index_workers() that
has us treat the heap relation as an inheritance parent, just to get a
RelOptInfo for the heap relation without running into similar trouble
with the index in get_relation_info(). Perhaps there's an argument to
be made for refactoring plan_create_index_workers() as a fix for this.

> 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()?

I don't know, but that seems like a good question.

--
Peter Geoghegan

Hi,

On 2018-07-09 09:59:58 -0700, Peter Geoghegan wrote:
> On Thu, Jun 28, 2018 at 8:02 AM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> > 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.
>
> Note that there is a kludge within plan_create_index_workers() that
> has us treat the heap relation as an inheritance parent, just to get a
> RelOptInfo for the heap relation without running into similar trouble
> with the index in get_relation_info(). Perhaps there's an argument to
> be made for refactoring plan_create_index_workers() as a fix for this.

Maybe I'm missing something, but what has this got to do with the issue
at hand?

> > 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()?
>
> I don't know, but that seems like a good question.

I assume we'll have to backpatch this issue, so I think it'd probably a
good idea to put a specific CacheInvalidateHeapTuple() in there
explicitly in the back branches, and do the larger fix in 12. ISTM
there's some risks that it'd cause issues. Will you tackle this?

Greetings,

Andres Freund

On Mon, Jul 9, 2018 at 11:32 AM, Andres Freund <andres(at)anarazel(dot)de> wrote:
>> Note that there is a kludge within plan_create_index_workers() that
>> has us treat the heap relation as an inheritance parent, just to get a
>> RelOptInfo for the heap relation without running into similar trouble
>> with the index in get_relation_info(). Perhaps there's an argument to
>> be made for refactoring plan_create_index_workers() as a fix for this.
>
> Maybe I'm missing something, but what has this got to do with the issue
> at hand?

Nothing. It might be worthwhile to find a way to not do that as part
of fixing this issue, though. Just a suggestion.

> I assume we'll have to backpatch this issue, so I think it'd probably a
> good idea to put a specific CacheInvalidateHeapTuple() in there
> explicitly in the back branches, and do the larger fix in 12. ISTM
> there's some risks that it'd cause issues. Will you tackle this?

Okay.

--
Peter Geoghegan

Hi,

On 2018-07-09 12:06:21 -0700, Peter Geoghegan wrote:
> > I assume we'll have to backpatch this issue, so I think it'd probably a
> > good idea to put a specific CacheInvalidateHeapTuple() in there
> > explicitly in the back branches, and do the larger fix in 12. ISTM
> > there's some risks that it'd cause issues. Will you tackle this?
>
> Okay.

Any progress on that?

Peter, given that your patch made this more likely, and that you're a
committer these days, I'm opening an open items entry, and assign it to
you. Does that sound ok?

Greetings,

Andres Freund

Hi,

On 2018-06-28 08:02:10 -0700, Andres Freund wrote:
> 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;
> }

Tom, do you have any comments about the above? The biggest argument
against hardcoding that a pg_index update also invalidates the
corresponding relation, is that there's a lot of other things that we
could handle similarly. But I don't think any of those are as important
to relcache entries...

Greetings,

Andres Freund

Andres Freund <andres(at)anarazel(dot)de> writes:
> On 2018-06-28 08:02:10 -0700, Andres Freund wrote:
>> I wonder why we don't just generally trigger invalidations to an
>> indexes' "owning" relation in CacheInvalidateHeapTuple()?

> Tom, do you have any comments about the above?

It seems like an ugly and fragile hack, offhand. I can see the point
about needing to recompute the owning relation's index list, but there's
no good reason why an update of a pg_index row ought to force that.
You're using that as a proxy for creation or deletion of an index, but
(at least in principle) pg_index rows might get updated for existing
indexes.

Also, it's not clear to me why the existing places that force relcache
inval on the owning table during index create/delete aren't sufficient
already. I suppose it's probably a timing problem, but it's not clear
why hacking CacheInvalidateHeapTuple in this fashion fixes that, or why
we could expect it to stay fixed.

regards, tom lane

On Wed, Jul 25, 2018 at 4:03 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> Peter, given that your patch made this more likely, and that you're a
> committer these days, I'm opening an open items entry, and assign it to
> you. Does that sound ok?

I intend to follow through on this soon. I have been distracted by
project work. I accept responsibility for the open item, though.

--
Peter Geoghegan

On 2018-07-25 19:27:47 -0400, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > On 2018-06-28 08:02:10 -0700, Andres Freund wrote:
> >> I wonder why we don't just generally trigger invalidations to an
> >> indexes' "owning" relation in CacheInvalidateHeapTuple()?
>
> > Tom, do you have any comments about the above?
>
> It seems like an ugly and fragile hack, offhand. I can see the point
> about needing to recompute the owning relation's index list, but there's
> no good reason why an update of a pg_index row ought to force that.
> You're using that as a proxy for creation or deletion of an index, but
> (at least in principle) pg_index rows might get updated for existing
> indexes.

Sure, but in at least some of those cases you'd also need to update the
list, as it could invalidate things like the determination of the oid,
pkey or whatnot index. But yea, I don't think it's a *great* idea, just
an idea worth considering.

> Also, it's not clear to me why the existing places that force relcache
> inval on the owning table during index create/delete aren't sufficient
> already. I suppose it's probably a timing problem, but it's not clear
> why hacking CacheInvalidateHeapTuple in this fashion fixes that, or why
> we could expect it to stay fixed.

Hm? As I point out in my email, there's simply nothing forcing an
invalidation in the relevant path? We register an invalidation, but only
*after* successfully building the entire index. So if the index build
fails, but we actually accessed the relcache (as e.g. the new
plan_create_index_workers() pretty much always does), the relcache entry
refers to the failed index build. I think it's basically a failure to
follow proper invalidation procedures - when modifying something
affecting a relcache entry it's not OK to delay the
CacheInvalidateRelcacheByTuple() to after a point where we can fail
nonFATALy.

Greetings,

Andres Freund

On Mon, Jul 9, 2018 at 11:32 AM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> I assume we'll have to backpatch this issue, so I think it'd probably a
> good idea to put a specific CacheInvalidateHeapTuple() in there
> explicitly in the back branches, and do the larger fix in 12. ISTM
> there's some risks that it'd cause issues.

What do you think of the attached?

The is a new CacheInvalidateRelcache() call, rather than a new call to
CacheInvalidateRelcacheByTuple(), but those two things are equivalent
(I assume that you actually meant to say
CacheInvalidateRelcacheByTuple(), not CacheInvalidateHeapTuple()).

Since nobody seems to be that excited about the
CacheInvalidateHeapTuple() idea, I haven't pursued it.

--
Peter Geoghegan

On 2018-07-31 18:48:23 -0700, Peter Geoghegan wrote:
> On Mon, Jul 9, 2018 at 11:32 AM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> > I assume we'll have to backpatch this issue, so I think it'd probably a
> > good idea to put a specific CacheInvalidateHeapTuple() in there
> > explicitly in the back branches, and do the larger fix in 12. ISTM
> > there's some risks that it'd cause issues.
>
> What do you think of the attached?
>
> The is a new CacheInvalidateRelcache() call, rather than a new call to
> CacheInvalidateRelcacheByTuple(), but those two things are equivalent
> (I assume that you actually meant to say
> CacheInvalidateRelcacheByTuple(), not CacheInvalidateHeapTuple()).

Right.

> From 18ffbcc81c75525c73930ad3b5a63ae0873d2381 Mon Sep 17 00:00:00 2001
> From: Peter Geoghegan <pg(at)bowt(dot)ie>
> Date: Tue, 31 Jul 2018 18:33:30 -0700
> Subject: [PATCH] Add table relcache invalidation to index builds.
>
> It's necessary to make sure that owning tables have a relcache
> invalidation prior to advancing the command counter to make
> newly-entered catalog tuples for the index visible. inval.c must be
> able to roll back the local caches in the event of transaction abort.
> There is only a problem when CREATE INDEX transactions abort, since
> there is a generic invalidation once we reach index_update_stats().
>
> This bug is of long standing. Problems were made much more likely by
> the addition of parallel CREATE INDEX (commit 9da0cc35284), but it is
> strongly suspected that similar problems can be triggered without
> involving plan_create_index_workers().

Maybe expand a bit on this by saying that it's more likely "because
plan_create_index_workers() triggers a relcache entry to be (re-)built,
which previously did only happen in edge cases" or such?

> Bug diagnosed by Andres Freund.
>
> Author: Peter Geoghegan
> Reported-By: Luca Ferrari
> Discussion: https://postgr.es/m/CAKoxK+5fVodiCtMsXKV_1YAKXbzwSfp7DgDqUmcUAzeAhf=HEQ@mail.gmail.com
> Backpatch: 9.3-
> ---
> src/backend/catalog/index.c | 13 +++++++++++++
> 1 file changed, 13 insertions(+)
>
> diff --git a/src/backend/catalog/index.c b/src/backend/catalog/index.c
> index 8b276bc430..7036d72bd6 100644
> --- a/src/backend/catalog/index.c
> +++ b/src/backend/catalog/index.c
> @@ -1137,6 +1137,19 @@ index_create(Relation heapRelation,
> InvokeObjectPostCreateHookArg(RelationRelationId,
> indexRelationId, 0, is_internal);
>
> + /*
> + * Invalidate the relcache for the owning table, so that any local
> + * relcache entry for the new index built after CommandCounterIncrement
> + * won't become inconsistent in the event of transaction abort. inval.c
> + * must be able to roll back the local caches when aborting. Clearly it
> + * isn't useful to create an index whose definition results in a relcache
> + * entry for the index being allocated before commit, but the local caches
> + * cannot be allowed to become inconsistent under any circumstances.
> + * (There is only an issue when transactions abort because we'll reach
> + * index_update_stats when they commit.)
> + */

Not a fan of this comment. It doesn't really explain that well why it's
needed here, but then goes on to a relatively general explanation of why
cache invalidation is necessary. Why not just go for something like
"register relcache invalidation on the indexes' heap relation, to
maintain consistency of its index list"?

I wonder if it wouldn't be more appropriately placed closer to the
UpdateIndexRelation(), given that that's essentially what necessitates
the relcache flush?

Greetings,

Andres Freund

On Tue, Jul 31, 2018 at 7:02 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> Maybe expand a bit on this by saying that it's more likely "because
> plan_create_index_workers() triggers a relcache entry to be (re-)built,
> which previously did only happen in edge cases" or such?

Okay.

> Not a fan of this comment. It doesn't really explain that well why it's
> needed here, but then goes on to a relatively general explanation of why
> cache invalidation is necessary. Why not just go for something like
> "register relcache invalidation on the indexes' heap relation, to
> maintain consistency of its index list"?

That seems much more generic to me!

The comment is supposed to convey that the stuff within
index_update_stats() isn't enough because of xact abort specifically.
SI invalidation is very much part of the index_update_stats() contract
already.

> I wonder if it wouldn't be more appropriately placed closer to the
> UpdateIndexRelation(), given that that's essentially what necessitates
> the relcache flush?

That makes sense. I'll do it that way.

--
Peter Geoghegan

Hi,

On 2018-07-31 19:29:37 -0700, Peter Geoghegan wrote:
> On Tue, Jul 31, 2018 at 7:02 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> > Not a fan of this comment. It doesn't really explain that well why it's
> > needed here, but then goes on to a relatively general explanation of why
> > cache invalidation is necessary. Why not just go for something like
> > "register relcache invalidation on the indexes' heap relation, to
> > maintain consistency of its index list"?
>
> That seems much more generic to me!
>
> The comment is supposed to convey that the stuff within
> index_update_stats() isn't enough because of xact abort specifically.
> SI invalidation is very much part of the index_update_stats() contract
> already.

I don't think that's particularly relevant. We should always register an
invalidation before the relevant CommandCounterIncrement(), because that
is what makes catalog changes visible, and therefore requires
registering invalidations for coherency. That we possibly later, in
another CCI cycle, reach yet another invalidation point, doesn't matter
much (except that it can hide a lot of omissions). By your logic we'd
need an equivalent of the above comment at most of those places.

Greetings,

Andres Freund

On Tue, Jul 31, 2018 at 9:00 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> I don't think that's particularly relevant. We should always register an
> invalidation before the relevant CommandCounterIncrement(), because that
> is what makes catalog changes visible, and therefore requires
> registering invalidations for coherency.

Fair enough. How about the attached revision?

--
Peter Geoghegan

Hi,

On 2018-08-02 13:00:16 -0700, Peter Geoghegan wrote:
> On Tue, Jul 31, 2018 at 9:00 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
> > I don't think that's particularly relevant. We should always register an
> > invalidation before the relevant CommandCounterIncrement(), because that
> > is what makes catalog changes visible, and therefore requires
> > registering invalidations for coherency.
>
> Fair enough. How about the attached revision?

Looks good to me, minus some optional nitpicks in the commit message
below.

> From 156be401c38f7884ed65641aa202b72b698f3e91 Mon Sep 17 00:00:00 2001
> From: Peter Geoghegan <pg(at)bowt(dot)ie>
> Date: Tue, 31 Jul 2018 18:33:30 -0700
> Subject: [PATCH v2] Add table relcache invalidation to index builds.
>
> It's necessary to make sure that owning tables have a relcache
> invalidation prior to advancing the command counter to make
> newly-entered catalog tuples for the index visible. inval.c must be
> able to roll back the local caches in the event of transaction abort.
> There is only a problem when CREATE INDEX transactions abort, since
> there is a generic invalidation once we reach index_update_stats().

s/roll back/maintain consistency of/. I'd also perhaps weaken the next
sentence, by adding a 'practically' or such, as a memory allocation
failure or such before the index build starts could cause this as well.

Greetings,

Andres Freund