Pg 15 devel crashes when fetching data from table using cursor

From: hubert depesz lubaczewski <depesz(at)depesz(dot)com>
To: PostgreSQL mailing lists <pgsql-bugs(at)lists(dot)postgresql(dot)org>
Subject: Pg 15 devel crashes when fetching data from table using cursor
Date: 2022-03-07 09:44:23
Message-ID: 20220307094423.GA24798@depesz.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

Hi,
I ran 15devel, compiled today, on Ryzen processor (amd64), with data for
explain.depesz.com.

In psql I ran:

#v+
=$ psql -U depesz_explain
psql (15devel)
Type "help" for help.

(depesz_explain(at)[local]:5430) 09:46:37 [depesz_explain]
$ begin;
BEGIN
Time: 0.312 ms
(depesz_explain(at)[local]:5430) 09:46:40 [depesz_explain]
*$ DECLARE csr CURSOR FOR select id, plan FROM plans_part_25 WHERE is_public and NOT is_deleted and NOT is_anonymized;
DECLARE CURSOR
Time: 1.486 ms
(depesz_explain(at)[local]:5430) 09:46:53 [depesz_explain]
*$ fetch 100 from csr;
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
Time: 92.067 ms
(@:) 09:47:03 []
?$
#v-

Pg logs show:

#v+
2022-03-07 09:46:37.179 CET depesz_explain(at)depesz_explain 526595 [local] LOG: connection authorized: user=depesz_explain database=depesz_explain application_name=psql
2022-03-07 09:46:40.082 CET depesz_explain(at)depesz_explain 526595 [local] LOG: duration: 0.235 ms statement: begin;
2022-03-07 09:46:53.933 CET depesz_explain(at)depesz_explain 526595 [local] LOG: duration: 1.348 ms statement: DECLARE csr CURSOR FOR select id, plan FROM plans_part_25 WHERE is_public and NOT is_deleted and NOT is_anonymized;
TRAP: FailedAssertion("HaveRegisteredOrActiveSnapshot()", File: "toast_internals.c", Line: 670, PID: 526595)
postgres: depesz_explain depesz_explain [local] FETCH(ExceptionalCondition+0x99)[0x557da5491dc9]
postgres: depesz_explain depesz_explain [local] FETCH(+0x174f64)[0x557da5010f64]
postgres: depesz_explain depesz_explain [local] FETCH(heap_fetch_toast_slice+0x15f)[0x557da50606cf]
postgres: depesz_explain depesz_explain [local] FETCH(+0x16c374)[0x557da5008374]
postgres: depesz_explain depesz_explain [local] FETCH(detoast_attr+0x18d)[0x557da500884d]
postgres: depesz_explain depesz_explain [local] FETCH(text_to_cstring+0x16)[0x557da5467796]
postgres: depesz_explain depesz_explain [local] FETCH(OutputFunctionCall+0x58)[0x557da549c7c8]
postgres: depesz_explain depesz_explain [local] FETCH(+0x170fc5)[0x557da500cfc5]
postgres: depesz_explain depesz_explain [local] FETCH(+0x4cc4ee)[0x557da53684ee]
postgres: depesz_explain depesz_explain [local] FETCH(+0x4cc626)[0x557da5368626]
postgres: depesz_explain depesz_explain [local] FETCH(PortalRun+0x191)[0x557da5369e71]
postgres: depesz_explain depesz_explain [local] FETCH(+0x4c9ceb)[0x557da5365ceb]
postgres: depesz_explain depesz_explain [local] FETCH(PostgresMain+0x1708)[0x557da5367828]
postgres: depesz_explain depesz_explain [local] FETCH(+0x432073)[0x557da52ce073]
postgres: depesz_explain depesz_explain [local] FETCH(PostmasterMain+0xd5d)[0x557da52cf0ad]
postgres: depesz_explain depesz_explain [local] FETCH(main+0x20f)[0x557da4ff99bf]
/lib/x86_64-linux-gnu/libc.so.6(+0x29fd0)[0x7f7ba79dcfd0]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x7d)[0x7f7ba79dd07d]
postgres: depesz_explain depesz_explain [local] FETCH(_start+0x25)[0x557da4ff9d15]
2022-03-07 09:47:03.298 CET @ 508510 LOG: server process (PID 526595) was terminated by signal 6: Aborted
2022-03-07 09:47:03.298 CET @ 508510 DETAIL: Failed process was running: fetch 100 from csr;
2022-03-07 09:47:03.298 CET @ 508510 LOG: terminating any other active server processes
2022-03-07 09:47:03.299 CET [unknown](at)[unknown] 527019 [local] LOG: connection received: host=[local]
2022-03-07 09:47:03.299 CET depesz_explain(at)depesz_explain 527019 [local] FATAL: the database system is in recovery mode
2022-03-07 09:47:03.299 CET @ 508510 LOG: all server processes terminated; reinitializing
2022-03-07 09:47:03.316 CET @ 527022 LOG: database system was interrupted; last known up at 2022-03-07 09:45:57 CET
2022-03-07 09:47:03.558 CET @ 527022 LOG: database system was not properly shut down; automatic recovery in progress
2022-03-07 09:47:03.566 CET @ 527022 LOG: redo starts at 0/F61B64E0
2022-03-07 09:47:03.566 CET @ 527022 LOG: invalid record length at 0/F61B6518: wanted 24, got 0
2022-03-07 09:47:03.566 CET @ 527022 LOG: redo done at 0/F61B64E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-03-07 09:47:03.578 CET @ 527023 LOG: checkpoint starting: end-of-recovery immediate wait
2022-03-07 09:47:03.585 CET @ 527023 LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.008 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
2022-03-07 09:47:03.587 CET @ 508510 LOG: database system is ready to accept connections
#v-

Interestingly, I can select the data if I don't use cursor:

#v+
$ select id, plan FROM plans_part_25 WHERE is_public and NOT is_deleted and NOT is_anonymized \g | wc
1162074 11448274 1337357239722
Time: 213.767 ms
#v-

Details about the table:

#v+
$ \d+ plans_part_25
Table "public.plans_part_25"
Column │ Type │ Collation │ Nullable │ Default │ Storage │ Compression │ Stats target │ Description
──────────────────┼──────────────────────────┼───────────┼──────────┼─────────┼──────────┼─────────────┼──────────────┼─────────────
id │ text │ │ not null │ │ extended │ │ │
plan │ text │ │ not null │ │ extended │ │ │
entered_on │ timestamp with time zone │ │ not null │ now() │ plain │ │ │
is_public │ boolean │ │ not null │ true │ plain │ │ │
is_anonymized │ boolean │ │ not null │ false │ plain │ │ │
title │ text │ │ │ │ extended │ │ │
delete_key │ text │ │ │ │ extended │ │ │
is_deleted │ boolean │ │ not null │ false │ plain │ │ │
added_by │ text │ │ │ │ extended │ │ │
optimization_for │ text │ │ │ │ extended │ │ │
query │ text │ │ │ │ extended │ │ │
Partition of: plans FOR VALUES WITH (modulus 50, remainder 25)
Partition constraint: satisfies_hash_partition('16523'::oid, 50, 25, id)
Indexes:
"part_25_pkey" PRIMARY KEY, btree (id)
"part_25_added_by_entered_on_id_idx" UNIQUE, btree (added_by, entered_on, id) WHERE is_deleted = false
"part_25_added_by_idx" btree (added_by)
"part_25_entered_on_idx" btree (entered_on)
"part_25_entered_on_idx1" btree (entered_on) WHERE is_public AND NOT is_deleted
"part_25_length_idx" btree (length(plan)) WHERE NOT is_anonymized AND is_public
"part_25_optimization_for_idx" btree (optimization_for) WHERE NOT is_deleted
Access method: heap

$ select pg_column_compression(plan), count(*) FROM plans_part_25 WHERE is_public and NOT is_deleted and NOT is_anonymized group by 1;
pg_column_compression │ count
───────────────────────┼───────
[null] │ 3272
pglz │ 6556
(2 rows)
#v-

Information about compilation:

#v+
=$ pg_config --configure
'--prefix=/home/pgdba/work' '--with-pgport=5430' '--with-tcl' '--with-perl' '--with-python' '--enable-integer-datetimes' '--without-pam' '--without-bonjour' '--with-openssl' '--with-uuid=ossp' '--with-readline' '--with-libxml' '--with-systemd' '--with-zlib' '--with-lz4' '--with-llvm' '--with-gnu-ld' '--enable-debug' '--enable-depend' '--enable-cassert' 'PYTHON=/usr/bin/python3'

=$ dpkg -l | grep -iE '^ii[[:space:]]*(lib)?(gcc|clang|llvm|lz4|zlib)'
ii clang 1:13.0-53~exp1 amd64 C, C++ and Objective-C compiler (LLVM based), clang binary
ii clang-13 1:13.0.0-2 amd64 C, C++ and Objective-C compiler
ii gcc 4:11.2.0-1ubuntu1 amd64 GNU C compiler
ii gcc-11 11.2.0-7ubuntu2 amd64 GNU C compiler
ii gcc-11-aarch64-linux-gnu 11.2.0-5ubuntu1cross1 amd64 GNU C compiler (cross compiler for arm64 architecture)
ii gcc-11-aarch64-linux-gnu-base:amd64 11.2.0-5ubuntu1cross1 amd64 GCC, the GNU Compiler Collection (base package)
ii gcc-11-base:amd64 11.2.0-7ubuntu2 amd64 GCC, the GNU Compiler Collection (base package)
ii gcc-11-cross-base 11.2.0-5ubuntu1cross1 all GCC, the GNU Compiler Collection (library base package)
ii gcc-aarch64-linux-gnu 4:11.2.0-1ubuntu1 amd64 GNU C compiler for the arm64 architecture
ii libclang-common-13-dev 1:13.0.0-2 amd64 Clang library - Common development package
ii libclang-cpp13 1:13.0.0-2 amd64 C++ interface to the Clang library
ii libclang1-13 1:13.0.0-2 amd64 C interface to the Clang library
ii libgcc-11-dev:amd64 11.2.0-7ubuntu2 amd64 GCC support library (development files)
ii libgcc-11-dev-arm64-cross 11.2.0-5ubuntu1cross1 all GCC support library (development files)
ii libgcc-s1:amd64 11.2.0-7ubuntu2 amd64 GCC support library
ii libgcc-s1-arm64-cross 11.2.0-5ubuntu1cross1 all GCC support library (arm64)
ii libllvm12:amd64 1:12.0.1-8build1 amd64 Modular compiler and toolchain technologies, runtime library
ii libllvm13:amd64 1:13.0.0-2 amd64 Modular compiler and toolchain technologies, runtime library
ii liblz4-1:amd64 1.9.3-2 amd64 Fast LZ compression algorithm library - runtime
ii liblz4-dev:amd64 1.9.3-2 amd64 Fast LZ compression algorithm library - development files
ii llvm 1:13.0-53~exp1 amd64 Low-Level Virtual Machine (LLVM)
ii llvm-13 1:13.0.0-2 amd64 Modular compiler and toolchain technologies
ii llvm-13-dev 1:13.0.0-2 amd64 Modular compiler and toolchain technologies, libraries and headers
ii llvm-13-linker-tools 1:13.0.0-2 amd64 Modular compiler and toolchain technologies - Plugins
ii llvm-13-runtime 1:13.0.0-2 amd64 Modular compiler and toolchain technologies, IR interpreter
ii llvm-13-tools 1:13.0.0-2 amd64 Modular compiler and toolchain technologies, tools
ii llvm-runtime 1:13.0-53~exp1 amd64 Low-Level Virtual Machine (LLVM), bytecode interpreter
ii zlib1g:amd64 1:1.2.11.dfsg-2ubuntu7 amd64 compression library - runtime
ii zlib1g-dev:amd64 1:1.2.11.dfsg-2ubuntu7 amd64 compression library - development
#v-

depesz

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message David G. Johnston 2022-03-07 13:35:24 Re: BUG #17428: last_value incorrect for uninitialized sequence
Previous Message PG Bug reporting form 2022-03-07 00:31:33 BUG #17428: last_value incorrect for uninitialized sequence