On Tue, Aug 21, 2012 at 8:08 PM, Maxim Boguk <maxim.bo...@gmail.com> wrote:
> > > >> > >> > I have kept all that database files for the future investigation. >> > >> > What I should look into first? >> Could you reproduce the error with log_error_verbosity=verbose? Or even >> better >> provide a backtrace with gdb? >> >> > There log with log_error_verbosity=verbose: > > > 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOG: 00000: > database system was interrupted while in recovery at log time 2012-08-21 > 08:21:42 MSK > 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []HINT: If this > has occurred more than once some data might be corrupted and you might need > to choose an earlier recovery target. > 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOCATION: > StartupXLOG, xlog.c:5757 > 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOG: 00000: > creating missing WAL directory "pg_xlog/archive_status" > 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOCATION: > ValidateXLOGDirectoryStructure, xlog.c:3452 > 2012-08-21 14:04:19.009 MSK 33950 @ from [vxid: txid:0] []LOG: 00000: > entering standby mode > 2012-08-21 14:04:19.009 MSK 33950 @ from [vxid: txid:0] []LOCATION: > StartupXLOG, xlog.c:5827 > 2012-08-21 14:04:19.041 MSK 33951 @ from [vxid: txid:0] []LOG: 00000: > streaming replication successfully connected to primary > 2012-08-21 14:04:19.041 MSK 33951 @ from [vxid: txid:0] []LOCATION: > libpqrcv_connect, libpqwalreceiver.c:169 > 2012-08-21 14:04:20.140 MSK 33950 @ from [vxid:1/0 txid:0] []LOG: 00000: > redo starts at 925/2C0004C8 > 2012-08-21 14:04:20.140 MSK 33950 @ from [vxid:1/0 txid:0] []LOCATION: > StartupXLOG, xlog.c:6199 > 2012-08-21 14:04:20.160 MSK 33950 @ from [vxid:1/0 txid:0] []FATAL: > XX000: could not access status of transaction 361788644 > 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []DETAIL: > Could not read from file "pg_multixact/offsets/1590" at offset 114688: > Unknown error: 0. > 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []CONTEXT: > xlog redo create multixact 361788644 offset 822580965: 1768508061 1768508078 > 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []LOCATION: > SlruReportIOError, slru.c:840 > 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOG: 00000: > startup process (PID 33950) exited with exit code 1 > 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOCATION: > LogChildExit, postmaster.c:2840 > 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOG: 00000: > terminating any other active server processes > 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOCATION: > HandleChildCrash, postmaster.c:2674 > > I tried A bit play with more detailed debug info and got mode detailed log: LOG: 00000: database system was interrupted while in recovery at log time 2012-08-21 08:21:42 MSK HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target. LOCATION: StartupXLOG, xlog.c:5757 DEBUG: 00000: standby_mode = 'on' LOCATION: readRecoveryCommandFile, xlog.c:5269 DEBUG: 00000: primary_conninfo = 'host=10.12.22.19 port=5433 user=replica password=acilper' LOCATION: readRecoveryCommandFile, xlog.c:5276 DEBUG: 00000: trigger_file = '/db/data/failover' LOCATION: readRecoveryCommandFile, xlog.c:5283 LOG: 00000: entering standby mode LOCATION: StartupXLOG, xlog.c:5827 DEBUG: 00000: checkpoint record is at 925/2D41CAA0 LOCATION: StartupXLOG, xlog.c:5894 DEBUG: 00000: redo record is at 925/2C0004C8; shutdown FALSE LOCATION: StartupXLOG, xlog.c:5929 DEBUG: 00000: next transaction ID: 0/1768511856; next OID: 59880938 LOCATION: StartupXLOG, xlog.c:5933 DEBUG: 00000: next MultiXactId: 361788644; next MultiXactOffset: 822580965 LOCATION: StartupXLOG, xlog.c:5936 DEBUG: 00000: oldest unfrozen transaction ID: 1569182525, in database 16424 LOCATION: StartupXLOG, xlog.c:5939 DEBUG: 00000: transaction ID wrap limit is 3716666172, limited by database with OID 16424 LOCATION: SetTransactionIdLimit, varsup.c:334 DEBUG: 00000: initializing for hot standby LOCATION: StartupXLOG, xlog.c:6070 DEBUG: 00000: my backend id is 1 LOCATION: SharedInvalBackendInit, sinvaladt.c:326 LOG: 00000: redo starts at 925/2C0004C8 LOCATION: StartupXLOG, xlog.c:6199 DEBUG: 00000: record known xact 1768508078 latestObservedXid 0 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508078 latestObservedXid 0 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: remove KnownAssignedXid 1768508078 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04 LOCATION: KnownAssignedXidsRemove, procarray.c:2869 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo exclusive_lock: xid 1768508080 rel 1663/16424/17282; tid 725829/8 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo update: rel 1663/16424/17282; tid 725829/8; new 726017/7 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508076 latestObservedXid 0 CONTEXT: xlog redo exclusive_lock: xid 1768508076 rel 1663/16424/47760635; tid 3075/136 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/47747; tid 43866/197 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/52546872; tid 44700/276 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508061 latestObservedXid 0 CONTEXT: xlog redo log: rel 1663/16424/19211 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508082 latestObservedXid 0 CONTEXT: xlog redo exclusive_lock: xid 1768508082 rel 1663/16424/4759107; tid 1098/7 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508076 latestObservedXid 0 CONTEXT: xlog redo hot_update: rel 1663/16424/47760635; tid 3075/136; new 3075/140 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo exclusive_lock: xid 1768508080 rel 1663/16424/17282; tid 725918/2 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508082 latestObservedXid 0 CONTEXT: xlog redo hot_update: rel 1663/16424/4759107; tid 1098/7; new 1098/39 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo update: rel 1663/16424/17282; tid 725918/2; new 725918/6 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/47747; tid 43866/201 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/52546872; tid 44700/276 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508080 latestObservedXid 0 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: remove KnownAssignedXid 1768508080 CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04 LOCATION: KnownAssignedXidsRemove, procarray.c:2869 DEBUG: 00000: record known xact 1768508061 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/64654; tid 178183/44 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508061 latestObservedXid 0 CONTEXT: xlog redo insert: rel 1663/16424/95419; tid 38650/318 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 DEBUG: 00000: record known xact 1768508061 latestObservedXid 0 CONTEXT: xlog redo create multixact 361788644 offset 822580965: 1768508061 1768508078 LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375 FATAL: XX000: could not access status of transaction 361788644 DETAIL: Could not read from file "pg_multixact/offsets/1590" at offset 114688: Unknown error: 0. CONTEXT: xlog redo create multixact 361788644 offset 822580965: 1768508061 1768508078 LOCATION: SlruReportIOError, slru.c:840 DEBUG: 00000: shmem_exit(1): 5 callbacks to make I have some problems with debug startup process with gdb... I following next sequence of commands (and got no useful results): [pgsql@db1 ~/tmp/postgresql-9.0.8]$ /usr/local/bin/gdb /usr/local/bin/postgres ... Reading symbols from /usr/local/bin/postgres...done. (gdb) b exit Breakpoint 1 at 0x44d38c (gdb) run -D /db/data_back/ Starting program: /usr/local/bin/postgres -D /db/data_back/ Program received signal SIGUSR1, User defined signal 1. 0x00000008018ddadc in select () from /lib/libc.so.7 (gdb) bt #0 0x00000008018ddadc in select () from /lib/libc.so.7 #1 0x000000000065641c in ServerLoop () at postmaster.c:1396 #2 0x0000000000655d05 in PostmasterMain (argc=3, argv=0x7fffffffead0) at postmaster.c:1097 #3 0x00000000005d974a in main (argc=3, argv=0x7fffffffead0) at main.c:188 (gdb) cont Continuing. Breakpoint 1, 0x000000080186bab0 in exit () from /lib/libc.so.7 (gdb) bt #0 0x000000080186bab0 in exit () from /lib/libc.so.7 #1 0x000000000067d0a6 in proc_exit (code=1) at ipc.c:137 #2 0x0000000000659933 in ExitPostmaster (status=1) at postmaster.c:4172 #3 0x0000000000657d2d in reaper (postgres_signal_arg=20) at postmaster.c:2354 #4 <signal handler called> #5 <signal handler called> #6 0x00000008018ddadc in select () from /lib/libc.so.7 #7 0x000000000065641c in ServerLoop () at postmaster.c:1396 #8 0x0000000000655d05 in PostmasterMain (argc=3, argv=0x7fffffffead0) at postmaster.c:1097 #9 0x00000000005d974a in main (argc=3, argv=0x7fffffffead0) at main.c:188 (gdb) cont Continuing. [Inferior 1 (process 98857) exited with code 01] (gdb) quit