AW: BUG #16045: vacuum_db crash and illegal memory alloc after pg_upgrade from PG11 to PG12

Hi Tomas,

Nice that you could reproduce it.
This was just the way I followed.

For your Info, here are my no-standard config params:

name | current_setting
------------------------------------+---------------------------------
application_name | psql
auto_explain.log_analyze | on
auto_explain.log_min_duration | 0
auto_explain.log_nested_statements | on
client_encoding | WIN1252
cluster_name | HB_DEV
data_checksums | on
DateStyle | ISO, DMY
default_text_search_config | pg_catalog.german
dynamic_shared_memory_type | windows
effective_cache_size | 8GB
lc_collate | C
lc_ctype | German_Germany.1252
lc_messages | C
lc_monetary | German_Germany.1252
lc_numeric | German_Germany.1252
lc_time | German_Germany.1252
log_destination | stderr
log_directory | N:/ZZ_log/pg_log_hbdev
log_error_verbosity | verbose
log_file_mode | 0640
log_line_prefix | WHB %a %t %i %e %2l:>
log_statement | mod
log_temp_files | 0
log_timezone | CET
logging_collector | on
maintenance_work_mem | 128MB
max_connections | 100
max_stack_depth | 2MB
max_wal_size | 1GB
min_wal_size | 80MB
pg_stat_statements.max | 5000
pg_stat_statements.track | all
random_page_cost | 1
search_path | public, archiv, ablage, admin
server_encoding | UTF8
server_version | 12.0
shared_buffers | 1GB
shared_preload_libraries | auto_explain,pg_stat_statements
temp_buffers | 32MB
TimeZone | CET
transaction_deferrable | off
transaction_isolation | read committed
transaction_read_only | off
update_process_title | off
wal_buffers | 16MB
wal_segment_size | 16MB
work_mem | 32MB
(48 rows)

Indeed, the database has UTF8 Encoding.

The Extended error-log (i have set auto_explain):

WHB psql 2019-10-09 15:45:03 CEST XX000 7:> ERROR: XX000: invalid memory alloc request size 18446744073709551613
WHB psql 2019-10-09 15:45:03 CEST XX000 8:> LOCATION: palloc, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\utils\mmgr\mcxt.c:934
WHB psql 2019-10-09 15:45:03 CEST XX000 9:> STATEMENT: select * from q_tbl_archiv;
WHB vacuumdb 2019-10-09 15:46:42 CEST 00000 1:> LOG: 00000: duration: 0.022 ms plan:
Query Text: SELECT pg_catalog.set_config('search_path', '', false);
Result (cost=0.00..0.01 rows=1 width=32) (actual time=0.014..0.015 rows=1 loops=1)
WHB vacuumdb 2019-10-09 15:46:42 CEST 00000 2:> LOCATION: explain_ExecutorEnd, d:\pginstaller_12.auto\postgres.windows-x64\contrib\auto_explain\auto_explain.c:415
WHB vacuumdb 2019-10-09 15:46:42 CEST 00000 3:> LOG: 00000: duration: 0.072 ms plan:
Query Text: SELECT datname FROM pg_database WHERE datallowconn ORDER BY 1;
Sort (cost=1.16..1.16 rows=1 width=64) (actual time=0.063..0.064 rows=14 loops=1)
Sort Key: datname
Sort Method: quicksort Memory: 26kB
-> Seq Scan on pg_database (cost=0.00..1.15 rows=1 width=64) (actual time=0.018..0.022 rows=14 loops=1)
Filter: datallowconn
Rows Removed by Filter: 1
WHB vacuumdb 2019-10-09 15:46:42 CEST 00000 4:> LOCATION: explain_ExecutorEnd, d:\pginstaller_12.auto\postgres.windows-x64\contrib\auto_explain\auto_explain.c:415
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 1:> LOG: 00000: duration: 0.027 ms plan:
Query Text: SELECT pg_catalog.set_config('search_path', '', false);
Result (cost=0.00..0.01 rows=1 width=32) (actual time=0.012..0.013 rows=1 loops=1)
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 2:> LOCATION: explain_ExecutorEnd, d:\pginstaller_12.auto\postgres.windows-x64\contrib\auto_explain\auto_explain.c:415
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 3:> LOG: 00000: duration: 1.036 ms plan:
Query Text: SELECT c.relname, ns.nspname FROM pg_catalog.pg_class c
JOIN pg_catalog.pg_namespace ns ON c.relnamespace OPERATOR(pg_catalog.=) ns.oid
LEFT JOIN pg_catalog.pg_class t ON c.reltoastrelid OPERATOR(pg_catalog.=) t.oid
WHERE c.relkind OPERATOR(pg_catalog.=) ANY (array['r', 'm'])
ORDER BY c.relpages DESC;
Sort (cost=56.56..56.59 rows=13 width=132) (actual time=0.843..0.854 rows=320 loops=1)
Sort Key: c.relpages DESC
Sort Method: quicksort Memory: 110kB
-> Hash Join (cost=1.23..56.32 rows=13 width=132) (actual time=0.082..0.649 rows=320 loops=1)
Hash Cond: (c.relnamespace = ns.oid)
-> Seq Scan on pg_class c (cost=0.00..55.05 rows=13 width=76) (actual time=0.034..0.545 rows=320 loops=1)
Filter: ((relkind)::text = ANY ('{r,m}'::text[]))
Rows Removed by Filter: 950
-> Hash (cost=1.10..1.10 rows=10 width=68) (actual time=0.022..0.022 rows=10 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
-> Seq Scan on pg_namespace ns (cost=0.00..1.10 rows=10 width=68) (actual time=0.010..0.011 rows=10 loops=1)
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 4:> LOCATION: explain_ExecutorEnd, d:\pginstaller_12.auto\postgres.windows-x64\contrib\auto_explain\auto_explain.c:415
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 5:> LOG: 00000: duration: 0.011 ms plan:
Query Text: SELECT pg_catalog.set_config('search_path', '', false);
Result (cost=0.00..0.01 rows=1 width=32) (actual time=0.008..0.008 rows=1 loops=1)
WHB vacuumdb 2019-10-09 15:46:43 CEST 00000 6:> LOCATION: explain_ExecutorEnd, d:\pginstaller_12.auto\postgres.windows-x64\contrib\auto_explain\auto_explain.c:415
WHB 2019-10-09 15:47:01 CEST 00000 22:> LOG: 00000: server process (PID 4708) was terminated by exception 0xC0000005
WHB 2019-10-09 15:47:01 CEST 00000 23:> DETAIL: Failed process was running: ANALYZE admin.q_tbl_archiv;
WHB 2019-10-09 15:47:01 CEST 00000 24:> HINT: See C include file "ntstatus.h" for a description of the hexadecimal value.
WHB 2019-10-09 15:47:01 CEST 00000 25:> LOCATION: LogChildExit, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\postmaster\postmaster.c:3670
WHB 2019-10-09 15:47:01 CEST 00000 26:> LOG: 00000: terminating any other active server processes
WHB 2019-10-09 15:47:01 CEST 00000 27:> LOCATION: HandleChildCrash, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\postmaster\postmaster.c:3400
WHB psql 2019-10-09 15:47:01 CEST 57P02 10:> WARNING: 57P02: terminating connection because of crash of another server process
WHB psql 2019-10-09 15:47:01 CEST 57P02 11:> DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
WHB psql 2019-10-09 15:47:01 CEST 57P02 12:> HINT: In a moment you should be able to reconnect to the database and repeat your command.
WHB psql 2019-10-09 15:47:01 CEST 57P02 13:> LOCATION: quickdie, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\tcop\postgres.c:2717
WHB 2019-10-09 15:47:02 CEST 57P02 3:> WARNING: 57P02: terminating connection because of crash of another server process
WHB 2019-10-09 15:47:02 CEST 57P02 4:> DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
WHB 2019-10-09 15:47:02 CEST 57P02 5:> HINT: In a moment you should be able to reconnect to the database and repeat your command.
WHB 2019-10-09 15:47:02 CEST 57P02 6:> LOCATION: quickdie, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\tcop\postgres.c:2717
WHB 2019-10-09 15:47:02 CEST 00000 28:> LOG: 00000: all server processes terminated; reinitializing
WHB 2019-10-09 15:47:02 CEST 00000 29:> LOCATION: PostmasterStateMachine, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\postmaster\postmaster.c:3912
WHB 2019-10-09 15:47:02 CEST 00000 1:> LOG: 00000: database system was interrupted; last known up at 2019-10-09 15:46:03 CEST
WHB 2019-10-09 15:47:02 CEST 00000 2:> LOCATION: StartupXLOG, d:\pginstaller_12.auto\postgres.windows-x64\src\backend\access\transam\xlog.c:6277

The table was imported successively by pg_dump/pg_restore from the previous versions into pg11.

This was the same what I did on the other machine (pg 11.5). On this test machine I could successfully Export the table with pg_dump -t.

On the erroneous PG12 Cluster I succeeded to recreate a similar table with the original create table Statements: no Errors.

Under PG12 upgraded, I tried to select only the first column (select table_name from q_tbl_archiv) and got erroneaus results (shown first 2 entries):

cpsdb=# select table_name from q_tbl_archiv;
table_name
---------------------------------------------
\x11chemmat\x17chm_season
!collectionsheet\x15cs_season

It seems that the length Bytes are present in the Output.

Hope this Information helps.

Hans Buschmann