pg.ddx.io pgsql-bugs@postgresql.org mailing list archive help / color / mirror / Atom feed From: Alexander Lakhin <exclusion@gmail.com>
To: Andres Freund <andres@anarazel.de>
To: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #17821: Assertion failed in heap_update() due to heap pruning
Date: Sat, 7 Oct 2023 11:00:00 +0300
Message-ID: <25c3399b-58a3-d727-7f97-93394fd1afa9@gmail.com> (raw )
In-Reply-To: <BEB9A06A-3B05-41DC-AEE4-AD3DC4AD67E5@anarazel.de >
References: <17821-dd8c334263399284@postgresql.org >
<13d30799-0107-6502-c81c-39ff5f1e7eb0@gmail.com >
<BEB9A06A-3B05-41DC-AEE4-AD3DC4AD67E5@anarazel.de >
Hi,
04.03.2023 19:48, Andres Freund wrote:
> My first suspicion would be that we aren't holding a lock in the right moment, to enforce cache invalidation processing.
>
I've encountered another case of that assertion failure (this time with pg_statistic):
numclients=10
for ((c=1;c<=numclients;c++)); do
createdb db$c
done
for ((i=1;i<=50;i++)); do
echo "iteration $i"
for ((c=1;c<=numclients;c++)); do
echo "
CREATE TABLE t(i int4, t1 text[], t2 text[]);
INSERT INTO t SELECT g, ARRAY[repeat('x', g)], ARRAY[repeat('x', g)] FROM generate_series(1, 200) g;
ANALYZE t;
" | psql -d db$c >/dev/null
done
for ((c=1;c<=numclients;c++)); do
echo "
ANALYZE t;
" | psql -d db$c >/dev/null &
echo "
SELECT * FROM t WHERE i = 1;
ANALYZE t;
" | psql -d db$c >/dev/null &
done
wait
grep 'TRAP:' server.log && { break; }
for ((c=1;c<=numclients;c++)); do
echo "
DROP TABLE t; VACUUM pg_statistic;
" | psql -d db$c >/dev/null
done
done
...
iteration 13
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
connection to server was lost
TRAP: failed Assert("ItemIdIsNormal(lp)"), File: "heapam.c", Line: 3074, PID: 89697
Reproduced on REL_12_STABLE (starting from 5e0928005) .. master.
(Modifying pruneheap.c as in [1] not needed for this case.)
Here we have the following sequence of events:
Session 1
ANALYZE t; // needed just to produce material for pruning
do_analyze_rel() -> update_attstats() -> CatalogTupleUpdateWithInfo() -> heap_update(ctid(18,16));
PrepareToInvalidateCacheTuple(hashvalue: {hash1})
Session 2:
SELECT * FROM t WHERE i = 1;
SearchCatCacheInternal(hashValue: {hash1})
SearchCatCacheMiss(hashValue: {hash1})
ProcessInvalidationMessages()
CatCacheInvalidate(hashValue: {hash1})
CatCacheInvalidate(hashValue: {hash2})
CatCacheInvalidate(hashValue: {hash1})
SearchCatCacheMiss returns tid(18,16)
ANALYZE t;
do_analyze_rel() -> update_attstats()
attno=0 SearchSysCache3() -> SearchCatCacheInternal(hashValue: {hash2}) -> SearchCatCacheMiss()
-> heap_page_prune(block: 18)
attno=1 SearchSysCache3() -> SearchCatCacheInternal(hashValue: {hash1}) -> oldtup = tid(18,16)
CatalogTupleUpdateWithInfo() -> heap_update(tid(18, 16))
(A server.log with additional tracing messages for one of the failed runs
is attached.)
In other words, a backend can get some tuple id from catcache and then prune
the underlying page while searching for another (missing) entry in the cache
(any other reading of the page that may trigger pruning will do as well).
After that, an attempt to update that tuple might trigger the Assert().
[1] https://www.postgresql.org/message-id/17821-dd8c334263399284%40postgresql.org
Best regards,
Alexander
Attachments:
server-db6.log (text/x-log, 23.9K) download
2023-10-07 10:02:26.542 MSK|law|postgres|65210282.3b728|LOG: statement: CREATE DATABASE db6;
2023-10-07 10:02:26.551 MSK|law|postgres|65210282.3b728|STATEMENT: CREATE DATABASE db6;
2023-10-07 10:02:26.680 MSK|law|db6|65210282.3b742|LOG: connection authenticated: user="law" method=trust (.../pg_hba.conf:117)
2023-10-07 10:02:26.680 MSK|law|db6|65210282.3b742|LOG: connection authorized: user=law database=db6 application_name=psql
2023-10-07 10:02:26.682 MSK|law|db6|65210282.3b742|LOG: statement: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 18759199
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: 18759199
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1141534850
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1141534850
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1081954613
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1081954613
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|STATEMENT: CREATE TABLE t(i int4, t1 text[], t2 text[]);
2023-10-07 10:02:26.683 MSK|law|db6|65210282.3b742|LOG: statement: INSERT INTO t SELECT g, ARRAY[repeat('x', g)], ARRAY[repeat('x', g)] FROM generate_series(1, 200) g;
2023-10-07 10:02:26.684 MSK|law|db6|65210282.3b742|LOG: statement: ANALYZE t;
2023-10-07 10:02:26.684 MSK|law|db6|65210282.3b742|LOG: !!!do_analyze_rel
2023-10-07 10:02:26.684 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.684 MSK|law|db6|65210282.3b742|LOG: !!!do_analyze_rel| numrows: 200
2023-10-07 10:02:26.684 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!do_analyze_rel| before update_attstats
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!update_attstats| before SearchSysCache3(), attno: 0
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: 869244076
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!update_attstats| before SearchSysCache3(), attno: 1
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: -1994117683
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!update_attstats| before SearchSysCache3(), attno: 2
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!SearchCatCacheMiss| returning NULL
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: -1923937160
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!do_analyze_rel| after update_attstats
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.685 MSK|law|db6|65210282.3b742|LOG: disconnection: session time: 0:00:00.005 user=law database=db6 host=[local]
2023-10-07 10:02:26.723 MSK|law|db6|65210282.3b775|LOG: connection authenticated: user="law" method=trust (.../pg_hba.conf:117)
2023-10-07 10:02:26.723 MSK|law|db6|65210282.3b775|LOG: connection authorized: user=law database=db6 application_name=psql
2023-10-07 10:02:26.723 MSK|law|db6|65210282.3b775|LOG: statement: ANALYZE t;
2023-10-07 10:02:26.723 MSK|law|db6|65210282.3b775|LOG: !!!do_analyze_rel
2023-10-07 10:02:26.723 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!do_analyze_rel| numrows: 200
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b779|LOG: connection authenticated: user="law" method=trust (.../pg_hba.conf:117)
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b779|LOG: connection authorized: user=law database=db6 application_name=psql
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!do_analyze_rel| before update_attstats
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| before SearchSysCache3(), attno: 0
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (17, 26)
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after heap_modify_tuple(), ItemPointerGetBlockNumber(&stup->t_self) 17, ItemPointerGetOffsetNumber(&stup->t_self): 26
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!heap_update| relation: 2619, buffer: 6550, ItemPointerGetBlockNumber(otid): 17, ItemPointerGetOffsetNumber(otid): 26
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: 869244076
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after CatalogTupleUpdateWithInfo()
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| before SearchSysCache3(), attno: 1
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (18, 16)
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after heap_modify_tuple(), ItemPointerGetBlockNumber(&stup->t_self) 18, ItemPointerGetOffsetNumber(&stup->t_self): 16
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|LOG: !!!heap_update| relation: 2619, buffer: 6551, ItemPointerGetBlockNumber(otid): 18, ItemPointerGetOffsetNumber(otid): 16
2023-10-07 10:02:26.724 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: statement: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: -1994117683
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after CatalogTupleUpdateWithInfo()
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| before SearchSysCache3(), attno: 2
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (19, 1)
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after heap_modify_tuple(), ItemPointerGetBlockNumber(&stup->t_self) 19, ItemPointerGetOffsetNumber(&stup->t_self): 1
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!heap_update| relation: 2619, buffer: 11207, ItemPointerGetBlockNumber(otid): 19, ItemPointerGetOffsetNumber(otid): 1
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!update_attstats| after CatalogTupleUpdateWithInfo()
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!do_analyze_rel| after update_attstats
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (17, 26)
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!ProcessInvalidationMessages
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!CatCacheInvalidate| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (18, 16)
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: -1923937160
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (19, 2)
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: SELECT * FROM t WHERE i = 1;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b775|LOG: disconnection: session time: 0:00:00.003 user=law database=db6 host=[local]
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: statement: ANALYZE t;
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|LOG: !!!do_analyze_rel
2023-10-07 10:02:26.725 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!do_analyze_rel| numrows: 200
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!do_analyze_rel| before update_attstats
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!update_attstats| before SearchSysCache3(), attno: 0
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| cache->cc_relname: pg_statistic, hashValue: 869244076
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!heap_page_prune() before heap_page_prune_execute(); relation: 2619, buffer: 6550, BufferGetBlockNumber(buffer): 17, prstate.nredirected: 0, prstate.ndead: 1, prstate.nunused: 0, prstate.nowunused[0]: -1, query: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!heap_page_prune| end
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!heap_page_prune() before heap_page_prune_execute(); relation: 2619, buffer: 6551, BufferGetBlockNumber(buffer): 18, prstate.nredirected: 0, prstate.ndead: 1, prstate.nunused: 0, prstate.nowunused[0]: -1, query: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!heap_page_prune| end
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheMiss| returning ct->tuple: (18, 17)
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!update_attstats| after heap_modify_tuple(), ItemPointerGetBlockNumber(&stup->t_self) 18, ItemPointerGetOffsetNumber(&stup->t_self): 17
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!heap_update| relation: 2619, buffer: 6551, ItemPointerGetBlockNumber(otid): 18, ItemPointerGetOffsetNumber(otid): 17
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!PrepareToInvalidateCacheTuple| relation: 2619, hashvalue: 869244076
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!update_attstats| after CatalogTupleUpdateWithInfo()
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!update_attstats| before SearchSysCache3(), attno: 1
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!SearchCatCacheInternal| cache->cc_relname: pg_statistic, hashValue: -1994117683
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|LOG: !!!update_attstats| after heap_modify_tuple(), ItemPointerGetBlockNumber(&stup->t_self) 18, ItemPointerGetOffsetNumber(&stup->t_self): 16
2023-10-07 10:02:26.726 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
2023-10-07 10:02:26.727 MSK|law|db6|65210282.3b779|LOG: !!!heap_update| relation: 2619, buffer: 6551, ItemPointerGetBlockNumber(otid): 18, ItemPointerGetOffsetNumber(otid): 16
2023-10-07 10:02:26.727 MSK|law|db6|65210282.3b779|STATEMENT: ANALYZE t;
TRAP: failed Assert("ItemIdIsNormal(lp)"), File: "heapam.c", Line: 3090, PID: 243577
postgres: law db6 [local] ANALYZE(ExceptionalCondition+0x69)[0x55e5ebc98e4c]
postgres: law db6 [local] ANALYZE(heap_update+0x579)[0x55e5eb7953c5]
postgres: law db6 [local] ANALYZE(simple_heap_update+0x62)[0x55e5eb7969f4]
postgres: law db6 [local] ANALYZE(CatalogTupleUpdateWithInfo+0x4d)[0x55e5eb83eaa2]
postgres: law db6 [local] ANALYZE(+0x25a936)[0x55e5eb8ba936]
postgres: law db6 [local] ANALYZE(+0x25d856)[0x55e5eb8bd856]
postgres: law db6 [local] ANALYZE(analyze_rel+0x2b0)[0x55e5eb8be0b7]
postgres: law db6 [local] ANALYZE(vacuum+0x4d2)[0x55e5eb950865]
postgres: law db6 [local] ANALYZE(ExecVacuum+0x96d)[0x55e5eb951224]
postgres: law db6 [local] ANALYZE(standard_ProcessUtility+0x6d2)[0x55e5ebb518a4]
postgres: law db6 [local] ANALYZE(ProcessUtility+0xb7)[0x55e5ebb51d89]
postgres: law db6 [local] ANALYZE(+0x4ef146)[0x55e5ebb4f146]
postgres: law db6 [local] ANALYZE(+0x4ef440)[0x55e5ebb4f440]
postgres: law db6 [local] ANALYZE(PortalRun+0x193)[0x55e5ebb4f842]
postgres: law db6 [local] ANALYZE(+0x4ebaac)[0x55e5ebb4baac]
postgres: law db6 [local] ANALYZE(PostgresMain+0x713)[0x55e5ebb4d92d]
postgres: law db6 [local] ANALYZE(+0x444c4d)[0x55e5ebaa4c4d]
postgres: law db6 [local] ANALYZE(+0x447c88)[0x55e5ebaa7c88]
postgres: law db6 [local] ANALYZE(+0x447e26)[0x55e5ebaa7e26]
postgres: law db6 [local] ANALYZE(BackgroundWorkerInitializeConnection+0x0)[0x55e5ebaa936b]
postgres: law db6 [local] ANALYZE(main+0x21a)[0x55e5eb9c5d9c]
postgres: law db6 [local] ANALYZE(_start+0x25)[0x55e5eb7335c5]
view thread (13+ messages) latest in thread
Message-ID: <25c3399b-58a3-d727-7f97-93394fd1afa9@gmail.com>
Permalink: ../25c3399b-58a3-d727-7f97-93394fd1afa9@gmail.com/
Also on: postgresql.org/message-id/25c3399b-58a3-d727-7f97-93394fd1afa9@gmail.com
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: exclusion@gmail.com, andres@anarazel.de, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #17821: Assertion failed in heap_update() due to heap pruning
In-Reply-To: <25c3399b-58a3-d727-7f97-93394fd1afa9@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox