2015-10-10 18:04 GMT+02:00 Dmitry Vasilyev <d.vasil...@postgrespro.ru>:
> Hello Tom! > > On Сб, 2015-10-10 at 10:55 -0500, Tom Lane wrote: > > Dmitry Vasilyev <d.vasil...@postgrespro.ru> writes: > > > I have written, what service stopped. This action is repeatable. > > > You can run command 'psql -c "do $$ unpack p,1x8 $$ language > > > plperlu;"' > > > and after this windows service will stop. > > > > Well, (a) that probably means that your plperl installation is > > broken, > > and (b) you still haven't convinced me that you had an actual service > > stop, and not just that the recovery time was longer than psql would > > wait before retrying the connection. Can you start a fresh psql > > session after waiting a few seconds? > > > > regards, tom lane > > This is knowned bug of perl: > > perl -e ' unpack p,1x8' > Segmentation fault (core dumped) > so it is expected behave. After any unexpected client fails, the server is restarted Regards Pavel > > backend of postgres is crashed, and windows service is stopped: > > C:\Users\vadv>sc query postgresql-X64-9.4 | findstr /i "STATE" > S > TATE : 1 STOPPED > > > The log you can see bellow: > > 2015-10-10 19:00:13 AST LOG: database system was interrupted; last > known up at 2015-10-10 18:54:47 AST > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: checkpoint record is at 0/16A01C8 > 2015-10-10 19:00:13 AST DEBUG: redo record is at 0/16A01C8; shutdown > TRUE > 2015-10-10 19:00:13 AST DEBUG: next transaction ID: 0/678; next OID: > 16393 > 2015-10-10 19:00:13 AST DEBUG: next MultiXactId: 1; next > MultiXactOffset: 0 > 2015-10-10 19:00:13 AST DEBUG: oldest unfrozen transaction ID: 667, in > database 1 > 2015-10-10 19:00:13 AST DEBUG: oldest MultiXactId: 1, in database 1 > 2015-10-10 19:00:13 AST DEBUG: transaction ID wrap limit is > 2147484314, limited by database with OID 1 > 2015-10-10 19:00:13 AST DEBUG: MultiXactId wrap limit is 2147483648, > limited by database with OID 1 > 2015-10-10 19:00:13 AST DEBUG: starting up replication slots > 2015-10-10 19:00:13 AST LOG: database system was not properly shut > down; automatic recovery in progress > 2015-10-10 19:00:13 AST DEBUG: resetting unlogged relations: cleanup 1 > init 0 > 2015-10-10 19:00:13 AST LOG: redo starts at 0/16A0230 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12057; tid 0/3 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12059; tid 1/3 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12060; tid 1/2 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11979; tid 31/63 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11984; tid 16/34 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11889; tid 67/5 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11894; tid 9/132 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11895; tid 18/81 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12003; tid 48/62 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12005; tid 28/16 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/12006; tid 27/24 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11950; tid 0/5 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11952; tid 1/3 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 80 to 17 > 2015-10-10 19:00:13 AST CONTEXT: xlog redo insert: rel > 1663/12135/11953; tid 1/5 > 2015-10-10 19:00:13 AST LOG: record with zero length at 0/16AB308 > 2015-10-10 19:00:13 AST LOG: redo done at 0/16AB2D8 > 2015-10-10 19:00:13 AST LOG: last completed transaction was at log > time 2015-10-10 18:55:09.464+03 > 2015-10-10 19:00:13 AST DEBUG: resetting unlogged relations: cleanup 0 > init 1 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 5 to 13 > 2015-10-10 19:00:13 AST DEBUG: performing replication slot checkpoint > 2015-10-10 19:00:13 AST DEBUG: attempting to remove WAL segments older > than log file 000000000000000000000000 > 2015-10-10 19:00:13 AST DEBUG: SlruScanDirectory invoking callback on > pg_multixact/offsets/0000 > 2015-10-10 19:00:13 AST DEBUG: SlruScanDirectory invoking callback on > pg_multixact/members/0000 > 2015-10-10 19:00:13 AST DEBUG: SlruScanDirectory invoking callback on > pg_multixact/offsets/0000 > 2015-10-10 19:00:13 AST DEBUG: oldest MultiXactId member is at offset > 0 > 2015-10-10 19:00:13 AST LOG: MultiXact member wraparound protections > are now enabled > 2015-10-10 19:00:13 AST DEBUG: MultiXact member stop limit is now > 4294914944 based on MultiXact 1 > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(0): 1 before_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(0): 3 on_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: proc_exit(0): 2 callbacks to make > 2015-10-10 19:00:13 AST DEBUG: exit(0) > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:13 AST DEBUG: reaping dead processes > 2015-10-10 19:00:13 AST LOG: database system is ready to accept > connections > 2015-10-10 19:00:13 AST LOG: autovacuum launcher started > 2015-10-10 19:00:13 AST DEBUG: InitPostgres > 2015-10-10 19:00:13 AST DEBUG: my backend ID is 1 > 2015-10-10 19:00:13 AST DEBUG: checkpointer updated shared memory > configuration values > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: forked new backend, pid=3432 > socket=1288 > 2015-10-10 19:00:13 AST DEBUG: StartTransaction > 2015-10-10 19:00:13 AST DEBUG: name: unnamed; > blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:13 AST DEBUG: CommitTransaction > 2015-10-10 19:00:13 AST DEBUG: name: unnamed; > blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: received inquiry for database 0 > 2015-10-10 19:00:13 AST DEBUG: writing stats file > "pg_stat_tmp/global.stat" > 2015-10-10 19:00:13 AST DEBUG: postgres child[3432]: starting with ( > 2015-10-10 19:00:13 AST DEBUG: postgres > 2015-10-10 19:00:13 AST DEBUG: ) > 2015-10-10 19:00:13 AST DEBUG: InitPostgres > 2015-10-10 19:00:13 AST DEBUG: my backend ID is 2 > 2015-10-10 19:00:13 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:13 AST DEBUG: StartTransaction > 2015-10-10 19:00:13 AST DEBUG: name: unnamed; > blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:13 AST FATAL: role "WIN-TDLBFCTPHT0$" does not exist > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(1): 1 before_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(1): 6 on_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: proc_exit(1): 3 callbacks to make > 2015-10-10 19:00:13 AST DEBUG: exit(1) > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:13 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:13 AST DEBUG: reaping dead processes > 2015-10-10 19:00:13 AST DEBUG: server process (PID 3432) exited with > exit code 1 > 2015-10-10 19:00:16 AST DEBUG: forked new backend, pid=148 socket=1288 > 2015-10-10 19:00:16 AST DEBUG: postgres child[148]: starting with ( > 2015-10-10 19:00:16 AST DEBUG: postgres > 2015-10-10 19:00:16 AST DEBUG: ) > 2015-10-10 19:00:16 AST DEBUG: InitPostgres > 2015-10-10 19:00:16 AST DEBUG: my backend ID is 2 > 2015-10-10 19:00:16 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:16 AST DEBUG: StartTransaction > 2015-10-10 19:00:16 AST DEBUG: name: unnamed; > blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:16 AST FATAL: role "vadv" does not exist > 2015-10-10 19:00:16 AST DEBUG: shmem_exit(1): 1 before_shmem_exit > callbacks to make > 2015-10-10 19:00:16 AST DEBUG: shmem_exit(1): 6 on_shmem_exit > callbacks to make > 2015-10-10 19:00:16 AST DEBUG: proc_exit(1): 3 callbacks to make > 2015-10-10 19:00:16 AST DEBUG: exit(1) > 2015-10-10 19:00:16 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:16 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:16 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:16 AST DEBUG: reaping dead processes > 2015-10-10 19:00:16 AST DEBUG: server process (PID 148) exited with > exit code 1 > 2015-10-10 19:00:20 AST DEBUG: forked new backend, pid=5024 > socket=1288 > 2015-10-10 19:00:20 AST DEBUG: postgres child[5024]: starting with ( > 2015-10-10 19:00:20 AST DEBUG: postgres > 2015-10-10 19:00:20 AST DEBUG: ) > 2015-10-10 19:00:20 AST DEBUG: InitPostgres > 2015-10-10 19:00:20 AST DEBUG: my backend ID is 2 > 2015-10-10 19:00:20 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:20 AST DEBUG: StartTransaction > 2015-10-10 19:00:20 AST DEBUG: name: unnamed; > blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:20 AST DEBUG: mapped win32 error code 2 to 2 > 2015-10-10 19:00:20 AST DEBUG: CommitTransaction > 2015-10-10 19:00:20 AST DEBUG: name: unnamed; > blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:32 AST DEBUG: StartTransactionCommand > 2015-10-10 19:00:32 AST STATEMENT: do $$ unpack p,1x8 $$ language > plperlu; > 2015-10-10 19:00:32 AST DEBUG: StartTransaction > 2015-10-10 19:00:32 AST STATEMENT: do $$ unpack p,1x8 $$ language > plperlu; > 2015-10-10 19:00:32 AST DEBUG: name: unnamed; > blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, > nestlvl: 1, children: > 2015-10-10 19:00:32 AST STATEMENT: do $$ unpack p,1x8 $$ language > plperlu; > 2015-10-10 19:00:32 AST DEBUG: ProcessUtility > 2015-10-10 19:00:32 AST STATEMENT: do $$ unpack p,1x8 $$ language > plperlu; > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST DEBUG: server process (PID 5024) was > terminated by exception 0xC0000005 > 2015-10-10 19:00:32 AST DETAIL: Failed process was running: do $$ > unpack p,1x8 $$ language plperlu; > 2015-10-10 19:00:32 AST HINT: See C include file "ntstatus.h" for a > description of the hexadecimal value. > 2015-10-10 19:00:32 AST LOG: server process (PID 5024) was terminated > by exception 0xC0000005 > 2015-10-10 19:00:32 AST DETAIL: Failed process was running: do $$ > unpack p,1x8 $$ language plperlu; > 2015-10-10 19:00:32 AST HINT: See C include file "ntstatus.h" for a > description of the hexadecimal value. > 2015-10-10 19:00:32 AST LOG: terminating any other active server > processes > 2015-10-10 19:00:32 AST DEBUG: sending SIGQUIT to process 1848 > 2015-10-10 19:00:32 AST DEBUG: sending SIGQUIT to process 968 > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: sending SIGQUIT to process 1100 > 2015-10-10 19:00:32 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:32 AST DEBUG: sending SIGQUIT to process 1856 > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:32 AST DEBUG: sending SIGQUIT to process 1104 > 2015-10-10 19:00:32 AST WARNING: terminating connection because of > crash of another server process > 2015-10-10 19:00:32 AST 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. > 2015-10-10 19:00:32 AST HINT: In a moment you should be able to > reconnect to the database and repeat your command. > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:32 AST DEBUG: writing stats file > "pg_stat/global.stat" > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST DEBUG: writing stats file > "pg_stat/db_12135.stat" > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST DEBUG: removing temporary stats file > "pg_stat_tmp/db_12135.stat" > 2015-10-10 19:00:32 AST DEBUG: writing stats file "pg_stat/db_0.stat" > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST DEBUG: removing temporary stats file > "pg_stat_tmp/db_0.stat" > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST DEBUG: reaping dead processes > 2015-10-10 19:00:32 AST LOG: all server processes terminated; > reinitializing > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: shmem_exit(1): 3 on_shmem_exit > callbacks to make > 2015-10-10 19:00:32 AST DEBUG: cleaning up dynamic shared memory > control segment with ID 851401618 > 2015-10-10 19:00:32 AST DEBUG: invoking > IpcMemoryCreate(size=290095104) > 2015-10-10 19:00:42 AST FATAL: pre-existing shared memory block is > still in use > 2015-10-10 19:00:42 AST HINT: Check if there are any old server > processes still running, and terminate them. > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: proc_exit(1): 2 callbacks to make > 2015-10-10 19:00:42 AST DEBUG: exit(1) > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(-1): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(-1): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: proc_exit(-1): 0 callbacks to make > 2015-10-10 19:00:42 AST DEBUG: logger shutting down > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(0): 0 before_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: shmem_exit(0): 0 on_shmem_exit > callbacks to make > 2015-10-10 19:00:42 AST DEBUG: proc_exit(0): 0 callbacks to make > 2015-10-10 19:00:42 AST DEBUG: exit(0) > > > > > -- > Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-hackers >
