Issues shutting down PostgreSQL 10 cleanly

From: Stephen Froehlich <s(dot)froehlich(at)cablelabs(dot)com>
To: "pgsql-general(at)postgresql(dot)org" <pgsql-general(at)postgresql(dot)org>
Subject: Issues shutting down PostgreSQL 10 cleanly
Date: 2017-10-20 17:34:13
Message-ID: DM5PR06MB28916FD17718D597E62CD31FE5430@DM5PR06MB2891.namprd06.prod.outlook.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

I am in the midst of heavy, large write operations on a new database this is currently around 23 billion lines.

My max_wal_size is 256 GB and my checkpoint_timeout is 12 hours. (Smaller values were hindering the writes.) Note: this is on Ubuntu 16.04 LTS.

I am having trouble shutting down postgres cleanly - how can I fix that?

A "/etc/init.d/postgresql restart" command gave the following log entries:

2017-10-20 09:17:55.069 MDT [16388] LOG: received fast shutdown request
2017-10-20 09:17:55.069 MDT [16388] LOG: aborting any active transactions
2017-10-20 09:17:55.069 MDT [20336] FATAL: terminating autovacuum process due to administrator command
2017-10-20 09:17:55.069 MDT [20540] FATAL: terminating autovacuum process due to administrator command
2017-10-20 09:17:55.069 MDT [20132] FATAL: terminating autovacuum process due to administrator command
2017-10-20 09:17:55.070 MDT [1486] sfroehlich(at)mediacom_df_vd FATAL: terminating connection due to administrator command
2017-10-20 09:17:55.070 MDT [1488] sfroehlich(at)mediacom_df_vd FATAL: terminating connection due to administrator command
2017-10-20 09:17:55.070 MDT [1487] sfroehlich(at)mediacom_df_vd FATAL: terminating connection due to administrator command
2017-10-20 09:17:55.070 MDT [1489] sfroehlich(at)mediacom_df_vd FATAL: terminating connection due to administrator command
2017-10-20 09:17:55.070 MDT [1485] sfroehlich(at)mediacom_df_vd FATAL: terminating connection due to administrator command
2017-10-20 09:17:55.074 MDT [16388] LOG: worker process: logical replication launcher (PID 16400) exited with exit code 1
2017-10-20 09:19:08.363 MDT [16395] LOG: shutting down
2017-10-20 09:20:29.559 MDT [32352] LOG: listening on IPv4 address "0.0.0.0", port 5432
2017-10-20 09:20:29.559 MDT [32352] LOG: listening on IPv6 address "::", port 5432
2017-10-20 09:20:29.560 MDT [32352] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2017-10-20 09:20:57.956 MDT [32454] LOG: database system shutdown was interrupted; last known up at 2017-10-20 09:19:08 MDT
2017-10-20 09:21:03.598 MDT [32454] LOG: database system was not properly shut down; automatic recovery in progress
2017-10-20 09:21:03.646 MDT [32454] LOG: redo starts at 972/DB0B0838
pg_ctl: server did not start in time
2017-10-20 09:21:29.645 MDT [32352] LOG: received smart shutdown request
2017-10-20 09:21:29.735 MDT [32558] LOG: shutting down
2017-10-20 09:21:30.019 MDT [32352] LOG: database system is shut down

Then single-user-mode restore gave the following output.

postgres(at)pisa:/usr/lib/postgresql/10/bin$ ./postgres --single -D /etc/postgresql/10/main/ -P -d 1
2017-10-20 09:24:59.669 MDT [33361] DEBUG: mmap(35192307712) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2017-10-20 09:25:00.077 MDT [33361] LOG: database system was shut down in recovery at 2017-10-20 09:21:29 MDT
2017-10-20 09:25:00.077 MDT [33361] DEBUG: checkpoint record is at 97F/4F7E7168
2017-10-20 09:25:00.077 MDT [33361] DEBUG: redo record is at 972/DB0B0838; shutdown FALSE
2017-10-20 09:25:00.077 MDT [33361] DEBUG: next transaction ID: 0:1194772; next OID: 966656
2017-10-20 09:25:00.077 MDT [33361] DEBUG: next MultiXactId: 1; next MultiXactOffset: 0
2017-10-20 09:25:00.077 MDT [33361] DEBUG: oldest unfrozen transaction ID: 548, in database 1
2017-10-20 09:25:00.077 MDT [33361] DEBUG: oldest MultiXactId: 1, in database 1
2017-10-20 09:25:00.077 MDT [33361] DEBUG: commit timestamp Xid oldest/newest: 0/0
2017-10-20 09:25:00.077 MDT [33361] DEBUG: transaction ID wrap limit is 2147484195, limited by database with OID 1
2017-10-20 09:25:00.077 MDT [33361] DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1
2017-10-20 09:25:00.077 MDT [33361] DEBUG: starting up replication slots
2017-10-20 09:25:00.077 MDT [33361] LOG: database system was not properly shut down; automatic recovery in progress
2017-10-20 09:25:00.078 MDT [33361] DEBUG: resetting unlogged relations: cleanup 1 init 0
2017-10-20 09:25:00.125 MDT [33361] LOG: redo starts at 972/DB0B0838
2017-10-20 10:35:05.773 MDT [33361] LOG: invalid record length at 97F/4F7E71D8: wanted 24, got 0
2017-10-20 10:35:05.773 MDT [33361] LOG: redo done at 97F/4F7E7168
2017-10-20 10:35:05.773 MDT [33361] LOG: last completed transaction was at log time 2017-10-20 09:17:46.905639-06
2017-10-20 10:35:05.774 MDT [33361] DEBUG: resetting unlogged relations: cleanup 0 init 1
2017-10-20 10:35:06.350 MDT [33361] DEBUG: performing replication slot checkpoint
2017-10-20 11:25:10.991 MDT [33361] DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1
2017-10-20 11:25:10.991 MDT [33361] DEBUG: MultiXact member stop limit is now 4294914944 based on MultiXact 1
2017-10-20 11:25:11.035 MDT [33361] DEBUG: loaded library "pgcrypto"

PostgreSQL stand-alone backend 10.0
backend> [Ctrl+D]

2017-10-20 11:30:31.268 MDT [33361] NOTICE: shutting down
2017-10-20 11:30:31.270 MDT [33361] DEBUG: performing replication slot checkpoint
2017-10-20 11:31:40.767 MDT [33361] NOTICE: database system is shut down

Thanks in advance for your help ...

--Stephen

Stephen Froehlich
Sr. Strategist, CableLabs(r)

s(dot)froehlich(at)cablelabs(dot)com
Tel: +1 (303) 661-3708

Browse pgsql-general by date

  From Date Subject
Next Message Kim Rose Carlsen 2017-10-20 17:39:26 Replication stops under certain circumstances
Previous Message Tom Lane 2017-10-20 14:38:31 Re: How do you decide what aggregates to add?