BUG #16516: when testing jit get terminate called after throwing an instance of 'std::bad_function_call' - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      16516
Logged by:          reiner peterke
Email address:      reiner.peterke@splendiddata.com
PostgreSQL version: 12.3
Operating system:   Centos 7.8.2003, redhat 7.8, sles 12 sp5
Description:

Testing jit functionality power8 architecture
for Centos 7.8 Redhat 7.8 SUSE 12 sp15

Gave the following commands in psql:
> set jit_above_cost = 10;
> EXPLAIN ANALYZE SELECT SUM(relpages) FROM pg_class;

Expected result
Something like:

QUERY PLAN
--------------------------------------------------------------------------------------------------------------
Aggregate (cost=17.94..17.95 rows=1 width=8) (actual time=22.313..22.315
rows=1 loops=1)
-> Seq Scan on pg_class (cost=0.00..16.95 rows=395 width=4) (actual
time=0.024..0.644 rows=405 loops=1)
Planning Time: 30.354 ms
JIT:
Functions: 3
Options: Inlining false, Optimization false, Expressions true, Deforming
true
Timing: Generation 0.659 ms, Inlining 0.000 ms, Optimization 0.449 ms,
Emission 20.521 ms, Total 21.629 ms
Execution Time: 65.743 ms
(8 rows)

Observed result
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.
postgres server log

2020-06-25 12:27:29 CEST postgres postgres pid:7246 xid:0 ip:[local] LOG:
statement: set jit_above_cost=10;
2020-06-25 12:27:29 CEST postgres postgres pid:7246 xid:0 ip:[local] DEBUG:
CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS,
xid/subid/cid: 0/1/0
2020-06-25 12:27:35 CEST postgres postgres pid:7246 xid:0 ip:[local] DEBUG:
StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS,
xid/subid/cid: 0/1/0
2020-06-25 12:27:35 CEST postgres postgres pid:7246 xid:0 ip:[local] LOG:
statement: EXPLAIN ANALYZE SELECT SUM(relpages) FROM pg_class;
2020-06-25 12:27:35 CEST postgres postgres pid:7246 xid:0 ip:[local] DEBUG:
probing availability of JIT provider at
/usr/pgpure/postgres/12/lib/llvmjit.so
2020-06-25 12:27:35 CEST postgres postgres pid:7246 xid:0 ip:[local] DEBUG:
successfully loaded JIT provider in current session
2020-06-25 12:27:35 CEST postgres postgres pid:7246 xid:0 ip:[local] DEBUG:
LLVMJIT detected CPU "pwr8", with features ""
terminate called after throwing an instance of 'std::bad_function_call'
  what():  bad_function_call
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  server process (PID
7246) was terminated by signal 6: Aborted
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DETAIL:  Failed process was
running: EXPLAIN ANALYZE SELECT SUM(relpages) FROM pg_class;
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: LOG:  server process (PID
7246) was terminated by signal 6: Aborted
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DETAIL:  Failed process was
running: EXPLAIN ANALYZE SELECT SUM(relpages) FROM pg_class;
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: LOG:  terminating any other
active server processes
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7244
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7239
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7238
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7240
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7241
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7242
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  sending SIGQUIT to
process 7243
2020-06-25 12:27:35 CEST   pid:7241 xid:0 ip: WARNING:  terminating
connection because of crash of another server process
2020-06-25 12:27:35 CEST   pid:7241 xid:0 ip: 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.
2020-06-25 12:27:35 CEST   pid:7241 xid:0 ip: HINT:  In a moment you should
be able to reconnect to the database and repeat your command.
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  writing stats file
"pg_stat/global.stat"
2020-06-25 12:27:35 CEST   pid:7242 xid:0 ip: DEBUG:  shmem_exit(-1): 0
before_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7242 xid:0 ip: DEBUG:  shmem_exit(-1): 0
on_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7242 xid:0 ip: DEBUG:  proc_exit(-1): 0
callbacks to make
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  writing stats file
"pg_stat/db_12738.stat"
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  removing temporary
stats file "pg_stat_tmp/db_12738.stat"
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  writing stats file
"pg_stat/db_0.stat"
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  forked new backend,
pid=7247 socket=9
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  removing temporary
stats file "pg_stat_tmp/db_0.stat"
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  shmem_exit(-1): 0
before_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  shmem_exit(-1): 0
on_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7243 xid:0 ip: DEBUG:  proc_exit(-1): 0
callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] FATAL:
the database system is in recovery mode
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
shmem_exit(1): 0 before_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
shmem_exit(1): 0 on_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
proc_exit(1): 1 callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
exit(1)
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
shmem_exit(-1): 0 before_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
shmem_exit(-1): 0 on_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST postgres postgres pid:7247 xid:0 ip:[local] DEBUG:
proc_exit(-1): 0 callbacks to make
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: LOG:  archiver process (PID
7242) exited with exit code 1
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  server process (PID
7247) exited with exit code 1
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: LOG:  all server processes
terminated; reinitializing
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  shmem_exit(1): 0
before_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  shmem_exit(1): 5
on_shmem_exit callbacks to make
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  cleaning up dynamic
shared memory control segment with ID 214548396
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  invoking
IpcMemoryCreate(size=149102592)
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  mmap(150994944) with
MAP_HUGETLB failed, huge pages disabled: No such file or directory
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  SlruScanDirectory
invoking callback on pg_notify/0000
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  removing file
"pg_notify/0000"
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  dynamic shared memory
system will support 308 segments
2020-06-25 12:27:35 CEST   pid:7236 xid:0 ip: DEBUG:  created dynamic shared
memory control segment 1679281884 (7408 bytes)
2020-06-25 12:27:35 CEST   pid:7248 xid:0 ip: LOG:  database system was
interrupted; last known up at 2020-06-25 12:27:22 CEST
2020-06-25 12:27:35 CEST   pid:7248 xid:0 ip: DEBUG:  removing all temporary
WAL segments
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  checkpoint record is
at 0/18000028
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  redo record is at
0/18000028; shutdown true
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  next transaction ID:
4106; next OID: 16465
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  next MultiXactId: 1;
next MultiXactOffset: 0
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  oldest unfrozen
transaction ID: 479, in database 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  oldest MultiXactId: 1,
in database 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  commit timestamp Xid
oldest/newest: 0/0
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  transaction ID wrap
limit is 2147484126, limited by database with OID 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  MultiXactId wrap limit
is 2147483648, limited by database with OID 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  starting up
replication slots
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  starting up
replication origin progress state
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: LOG:  database system was not
properly shut down; automatic recovery in progress
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  resetting unlogged
relations: cleanup 1 init 0
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: LOG:  invalid record length at
0/180000A0: wanted 24, got 0
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: LOG:  redo is not required
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  resetting unlogged
relations: cleanup 0 init 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  performing replication
slot checkpoint
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  attempting to remove
WAL segments older than log file 000000000000000000000017
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  MultiXactId wrap limit
is 2147483648, limited by database with OID 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  MultiXact member stop
limit is now 4294914944 based on MultiXact 1
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  shmem_exit(0): 1
before_shmem_exit callbacks to make
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  shmem_exit(0): 5
on_shmem_exit callbacks to make
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  proc_exit(0): 2
callbacks to make
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  exit(0)
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  shmem_exit(-1): 0
before_shmem_exit callbacks to make
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  shmem_exit(-1): 0
on_shmem_exit callbacks to make
2020-06-25 12:27:38 CEST   pid:7248 xid:0 ip: DEBUG:  proc_exit(-1): 0
callbacks to make
2020-06-25 12:27:38 CEST   pid:7236 xid:0 ip: DEBUG:  reaping dead
processes
2020-06-25 12:27:38 CEST   pid:7249 xid:0 ip: DEBUG:  checkpointer updated
shared memory configuration values
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  autovacuum launcher
started
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  InitPostgres
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  my backend ID is 1
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  StartTransaction(1)
name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7236 xid:0 ip: DEBUG:  starting background
worker process "logical replication launcher"
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  CommitTransaction(1)
name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7254 xid:0 ip: DEBUG:  received inquiry for
database 0
2020-06-25 12:27:38 CEST   pid:7254 xid:0 ip: DEBUG:  writing stats file
"pg_stat_tmp/global.stat"
2020-06-25 12:27:38 CEST   pid:7236 xid:0 ip: LOG:  database system is ready
to accept connections
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  logical replication
launcher started
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  InitPostgres
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  my backend ID is 2
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  StartTransaction(1)
name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  CommitTransaction(1)
name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  StartTransaction(1)
name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  CommitTransaction(1)
name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  StartTransaction(1)
name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7255 xid:0 ip: DEBUG:  CommitTransaction(1)
name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  StartTransaction(1)
name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid:
0/1/0
2020-06-25 12:27:38 CEST   pid:7252 xid:0 ip: DEBUG:  CommitTransaction(1)
name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0