Re: BUG #16516: when testing jit get terminate called after throwing an instance of 'std::bad_function_call'

Is this specific to power8 architecture only?

On Mon, Jun 29, 2020 at 2:19 PM PG Bug reporting form <
noreply(at)postgresql(dot)org> wrote:

> The following bug has been logged on the website:
>
> Bug reference: 16516
> Logged by: reiner peterke
> Email address: reiner(dot)peterke(at)splendiddata(dot)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
>
>

--
Highgo Software (Canada/China/Pakistan)
URL : www.highgo.ca
ADDR: 10318 WHALLEY BLVD, Surrey, BC
CELL：+923335449950 EMAIL: mailto:hamid(dot)akhtar(at)highgo(dot)ca
SKYPE: engineeredvirus