Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nR9uu-0007Zh-0E for pgsql-bugs@arkaria.postgresql.org; Mon, 07 Mar 2022 09:44:36 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1nR9ur-0007Cw-2a for pgsql-bugs@arkaria.postgresql.org; Mon, 07 Mar 2022 09:44:33 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nR9uq-0007Cn-NT for pgsql-bugs@lists.postgresql.org; Mon, 07 Mar 2022 09:44:32 +0000 Received: from lana.depesz.com ([88.198.49.178] helo=depesz.com) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nR9uj-0007nr-RD for pgsql-bugs@lists.postgresql.org; Mon, 07 Mar 2022 09:44:31 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=depesz.com; s=20170201; h=Content-Transfer-Encoding:Content-Type:MIME-Version:Reply-To: Message-ID:Subject:To:Sender:From:Date:Cc:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: In-Reply-To:References:List-Id:List-Help:List-Unsubscribe:List-Subscribe: List-Post:List-Owner:List-Archive; bh=jtcEYLfyRmmccOFGUf0h4mOuhgRruI7+5k5hO1wOi5I=; b=UO8wQ3nSipbI4eL0B3Hn2F37yq +qN68qs7n0dZbvBRrNy5ztmUs4P1W9xPq4c9MnnrierYbRLO4L9gngBzlnj9Ehs3RbouSAfYAl23c NC6Awrd7+6gXEJy1hNp1DMI0HNcUNDDVjRp0GtAwlMLTcYkN5CfYZZeo+oB0rjErAGhg=; Received: from lana.depesz.com ([88.198.49.178] helo=depesz.com) by depesz.com with esmtpa (Exim 4.92) (envelope-from ) id 1nR9uh-0004v1-IV for pgsql-bugs@lists.postgresql.org; Mon, 07 Mar 2022 10:44:23 +0100 Date: Mon, 7 Mar 2022 10:44:23 +0100 From: hubert depesz lubaczewski Sender: depesz@depesz.com To: PostgreSQL mailing lists Subject: Pg 15 devel crashes when fetching data from table using cursor Message-ID: <20220307094423.GA24798@depesz.com> Reply-To: depesz@depesz.com MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit User-Agent: Mutt/1.10.1 (2018-07-13) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk 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@[local]:5430) 09:46:37 [depesz_explain] $ begin; BEGIN Time: 0.312 ms (depesz_explain@[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@[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@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@depesz_explain 526595 [local] LOG: duration: 0.235 ms statement: begin; 2022-03-07 09:46:53.933 CET depesz_explain@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]@[unknown] 527019 [local] LOG: connection received: host=[local] 2022-03-07 09:47:03.299 CET depesz_explain@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