|
Hi,
I have a database that is meant to have high-performance for bulk insert operations. I've attached my postgres.conf file.
However, I'm seeing the following behaviour. At around 12:04, I have started the database. Then, I did a bulk insert and that completed. I then went on to kill postgres processes at 12:33 with SIGSEGV signal. I'm getting the following log excerpt:
< 2021-06-15 12:33:03.656 CEST > LOG: database system was interrupted; last known up at 2021-06-15 12:04:13 CEST
< 2021-06-15 12:33:03.656 CEST > DEBUG: removing all temporary WAL segments < 2021-06-15 12:33:04.525 CEST > DEBUG: checkpoint record is at 60/7C377C78 [snip]
< 2021-06-15 12:33:04.537 CEST > DEBUG: resetting unlogged relations: cleanup 1 init 0 < 2021-06-15 12:33:04.553 CEST > DEBUG: unlinked file "base/16384/107877" [... snip ... ] < 2021-06-15 12:33:27.556 CEST > DEBUG: copying base/16384/80948_init to base/16384/80948 < 2021-06-15 12:33:36.705 CEST > DEBUG: performing replication slot checkpoint < 2021-06-15 12:33:38.394 CEST > DEBUG: attempting to remove WAL segments older than log file 00000000000000600000007C < 2021-06-15 12:33:38.394 CEST > DEBUG: removing write-ahead log file "00000001000000600000007C" < 2021-06-15 12:33:38.403 CEST > DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1 < 2021-06-15 12:33:38.419 CEST > DEBUG: oldest MultiXactId member is at offset 1 < 2021-06-15 12:33:38.419 CEST > DEBUG: MultiXact member stop limit is now 4294914944 based on MultiXact 1 < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(0): 1 before_shmem_exit callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(0): 5 on_shmem_exit callbacks to make
So it looks as if the database jumps back "half an hour" to ensure consistent data. Everything in between is lost.
What would be configuration settings to look into to make this more stable? Is there a way to "force flush state to disk" from the application/through postgres API/SQL?
Thank you, Manuel |
Attachment:
postgres.conf
Description: postgres.conf
< 2021-06-15 12:33:03.104 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:03.105 CEST > LOG: system logger process (PID 26) was terminated by signal 11: Segmentation fault < 2021-06-15 12:33:03.524 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:03.542 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:03.560 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:03.595 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:03.595 CEST > LOG: all server processes terminated; reinitializing < 2021-06-15 12:33:03.595 CEST > DEBUG: shmem_exit(1): 0 before_shmem_exit callbacks to make < 2021-06-15 12:33:03.595 CEST > DEBUG: shmem_exit(1): 6 on_shmem_exit callbacks to make < 2021-06-15 12:33:03.595 CEST > DEBUG: cleaning up orphaned dynamic shared memory with ID 321415882 < 2021-06-15 12:33:03.595 CEST > DEBUG: cleaning up orphaned dynamic shared memory with ID 761384284 < 2021-06-15 12:33:03.595 CEST > DEBUG: cleaning up dynamic shared memory control segment with ID 1236980165 < 2021-06-15 12:33:03.615 CEST > DEBUG: invoking IpcMemoryCreate(size=209027072) < 2021-06-15 12:33:03.615 CEST > DEBUG: mmap(209715200) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory < 2021-06-15 12:33:03.654 CEST > DEBUG: SlruScanDirectory invoking callback on pg_notify/0000 < 2021-06-15 12:33:03.654 CEST > DEBUG: removing file "pg_notify/0000" < 2021-06-15 12:33:03.654 CEST > DEBUG: dynamic shared memory system will support 674 segments < 2021-06-15 12:33:03.654 CEST > DEBUG: created dynamic shared memory control segment 504513596 (16192 bytes) < 2021-06-15 12:33:03.656 CEST > LOG: database system was interrupted; last known up at 2021-06-15 12:04:13 CEST < 2021-06-15 12:33:03.656 CEST > DEBUG: removing all temporary WAL segments < 2021-06-15 12:33:04.525 CEST > DEBUG: checkpoint record is at 60/7C377C78 < 2021-06-15 12:33:04.526 CEST > DEBUG: redo record is at 60/7C377C78; shutdown true < 2021-06-15 12:33:04.526 CEST > DEBUG: next transaction ID: 805913; next OID: 1004988 < 2021-06-15 12:33:04.526 CEST > DEBUG: next MultiXactId: 140; next MultiXactOffset: 283 < 2021-06-15 12:33:04.526 CEST > DEBUG: oldest unfrozen transaction ID: 479, in database 1 < 2021-06-15 12:33:04.526 CEST > DEBUG: oldest MultiXactId: 1, in database 1 < 2021-06-15 12:33:04.526 CEST > DEBUG: commit timestamp Xid oldest/newest: 0/0 < 2021-06-15 12:33:04.526 CEST > DEBUG: transaction ID wrap limit is 2147484126, limited by database with OID 1 < 2021-06-15 12:33:04.526 CEST > DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1 < 2021-06-15 12:33:04.526 CEST > DEBUG: starting up replication slots < 2021-06-15 12:33:04.526 CEST > DEBUG: starting up replication origin progress state < 2021-06-15 12:33:04.526 CEST > LOG: database system was not properly shut down; automatic recovery in progress < 2021-06-15 12:33:04.537 CEST > DEBUG: resetting unlogged relations: cleanup 1 init 0 < 2021-06-15 12:33:04.553 CEST > DEBUG: unlinked file "base/16384/107877" [... snip ... ] < 2021-06-15 12:33:27.556 CEST > DEBUG: copying base/16384/80948_init to base/16384/80948 < 2021-06-15 12:33:36.705 CEST > DEBUG: performing replication slot checkpoint < 2021-06-15 12:33:38.394 CEST > DEBUG: attempting to remove WAL segments older than log file 00000000000000600000007C < 2021-06-15 12:33:38.394 CEST > DEBUG: removing write-ahead log file "00000001000000600000007C" < 2021-06-15 12:33:38.403 CEST > DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1 < 2021-06-15 12:33:38.419 CEST > DEBUG: oldest MultiXactId member is at offset 1 < 2021-06-15 12:33:38.419 CEST > DEBUG: MultiXact member stop limit is now 4294914944 based on MultiXact 1 < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(0): 1 before_shmem_exit callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(0): 5 on_shmem_exit callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: proc_exit(0): 2 callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: exit(0) < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make < 2021-06-15 12:33:38.428 CEST > DEBUG: proc_exit(-1): 0 callbacks to make < 2021-06-15 12:33:38.430 CEST > DEBUG: reaping dead processes < 2021-06-15 12:33:38.430 CEST > DEBUG: checkpointer updated shared memory configuration values < 2021-06-15 12:33:38.431 CEST > DEBUG: starting background worker process "logical replication launcher" < 2021-06-15 12:33:38.431 CEST > DEBUG: autovacuum launcher started < 2021-06-15 12:33:38.431 CEST > DEBUG: InitPostgres < 2021-06-15 12:33:38.431 CEST > LOG: database system is ready to accept connections < 2021-06-15 12:33:38.431 CEST > DEBUG: my backend ID is 1 < 2021-06-15 12:33:38.431 CEST > DEBUG: logical replication launcher started < 2021-06-15 12:33:38.431 CEST > DEBUG: InitPostgres < 2021-06-15 12:33:38.431 CEST > DEBUG: my backend ID is 2 < 2021-06-15 12:33:38.432 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: received inquiry for database 0 < 2021-06-15 12:33:38.432 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: writing stats file "pg_stat_tmp/global.stat" < 2021-06-15 12:33:38.432 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.432 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.442 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:38.442 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:49.326 CEST > DEBUG: forked new backend, pid=166 socket=9 < 2021-06-15 12:33:49.327 CEST > DEBUG: postgres child[166]: starting with ( < 2021-06-15 12:33:49.327 CEST > DEBUG: postgres < 2021-06-15 12:33:49.327 CEST > DEBUG: ) < 2021-06-15 12:33:49.327 CEST > DEBUG: InitPostgres < 2021-06-15 12:33:49.327 CEST > DEBUG: my backend ID is 3 < 2021-06-15 12:33:49.327 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:49.327 CEST > DEBUG: received password packet < 2021-06-15 12:33:49.331 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:49.331 CEST > DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:49.331 CEST > STATEMENT: SET TIME ZONE 'UTC' < 2021-06-15 12:33:49.332 CEST > LOG: statement: SET TIME ZONE 'UTC' < 2021-06-15 12:33:49.332 CEST > DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 < 2021-06-15 12:33:49.332 CEST > STATEMENT: SET TIME ZONE 'UTC'
