Hello hackers:

Our standby node got fatal after the crash recovery. The fatal error was caused 
in slru module,  i changed log level from ERROR to PANIC and got the following 
stack.


(gdb) bt
#0  0x00007f0cc47a1277 in raise () from /lib64/libc.so.6
#1  0x00007f0cc47a2968 in abort () from /lib64/libc.so.6
#2  0x0000000000a48347 in errfinish (dummy=dummy@entry=0) at elog.c:616
#3  0x00000000005315dd in SlruReportIOError (ctl=ctl@entry=0xfbad00 
<ClogCtlData>, pageno=1947, xid=xid@entry=63800060) at slru.c:1175
#4  0x0000000000533152 in SimpleLruReadPage (ctl=ctl@entry=0xfbad00 
<ClogCtlData>, pageno=1947, write_ok=write_ok@entry=true, 
xid=xid@entry=63800060) at slru.c:610
#5  0x0000000000533350 in SimpleLruReadPage_ReadOnly (ctl=ctl@entry=0xfbad00 
<ClogCtlData>, pageno=pageno@entry=1947, xid=xid@entry=63800060) at slru.c:680
#6  0x00000000005293fd in TransactionIdGetStatus (xid=xid@entry=63800060, 
lsn=lsn@entry=0x7ffd17fc5130) at clog.c:661
#7  0x000000000053574a in TransactionLogFetch (transactionId=63800060) at 
transam.c:79
#8  TransactionIdDidCommit (transactionId=transactionId@entry=63800060) at 
transam.c:129
#9 0x00000000004f1295 in HeapTupleHeaderAdvanceLatestRemovedXid 
(tuple=0x2aab27e936e0, latestRemovedXid=latestRemovedXid@entry=0x7ffd17fc51b0) 
at heapam.c:7672
#10 0x00000000005103e0 in btree_xlog_delete_get_latestRemovedXid 
(record=record@entry=0x4636c98) at nbtxlog.c:656
#11 0x0000000000510a19 in btree_xlog_delete (record=0x4636c98) at nbtxlog.c:707
#12 btree_redo (record=0x4636c98) at nbtxlog.c:1048
#13 0x00000000005544a1 in StartupXLOG () at xlog.c:7825
#14 0x00000000008185be in StartupProcessMain () at startup.c:226
#15 0x000000000058de15 in AuxiliaryProcessMain (argc=argc@entry=2, 
argv=argv@entry=0x7ffd17fc9430) at bootstrap.c:448
#16 0x0000000000813fe4 in StartChildProcess (type=StartupProcess) at 
postmaster.c:5804
#17 0x0000000000817eb0 in PostmasterMain (argc=argc@entry=3, 
argv=argv@entry=0x45ed6e0) at postmaster.c:1461
#18 0x00000000004991f4 in main (argc=3, argv=0x45ed6e0) at main.c:232
(gdb) p /x *record
$10 = {wal_segment_size = 0x40000000, read_page = 0x54f920, system_identifier = 
0x5e6e6ea4af938064, private_data = 0x7ffd17fc5390, ReadRecPtr = 0xe41e8fb28, 
EndRecPtr = 0xe41e8fbb0, decoded_record = 0x4634390, main_data = 0x4634c88, 
main_data_len = 0x54,
  main_data_bufsz = 0x1000, record_origin = 0x0, blocks = {{in_use = 0x1, rnode 
= {spcNode = 0x67f, dbNode = 0x7517968, relNode = 0x7517e81}, forknum = 0x0, 
blkno = 0x55f, flags = 0x0, has_image = 0x0, apply_image = 0x0, bkp_image = 
0x4632bc1, hole_offset = 0x40,
      hole_length = 0x1fb0, bimg_len = 0x50, bimg_info = 0x5, has_data = 0x0, 
data = 0x4656938, data_len = 0x0, data_bufsz = 0x2000}, {in_use = 0x0, rnode = 
{spcNode = 0x67f, dbNode = 0x7517968, relNode = 0x7517e2b}, forknum = 0x0, 
blkno = 0x3b5f, flags = 0x80,
      has_image = 0x0, apply_image = 0x0, bkp_image = 0x0, hole_offset = 0x0, 
hole_length = 0x0, bimg_len = 0x0, bimg_info = 0x0, has_data = 0x0, data = 
0x46468e8, data_len = 0x0, data_bufsz = 0x2000}, {in_use = 0x0, rnode = 
{spcNode = 0x67f, dbNode = 0x7517968,
        relNode = 0x7e5c370}, forknum = 0x0, blkno = 0x2c3, flags = 0x80, 
has_image = 0x0, apply_image = 0x0, bkp_image = 0x0, hole_offset = 0x0, 
hole_length = 0x0, bimg_len = 0x0, bimg_info = 0x0, has_data = 0x0, data = 0x0, 
data_len = 0x0, data_bufsz = 0x0}, {
      in_use = 0x0, rnode = {spcNode = 0x67f, dbNode = 0x7517968, relNode = 
0x7517e77}, forknum = 0x0, blkno = 0xa8a, flags = 0x80, has_image = 0x0, 
apply_image = 0x0, bkp_image = 0x0, hole_offset = 0x0, hole_length = 0x0, 
bimg_len = 0x0, bimg_info = 0x0,
      has_data = 0x0, data = 0x0, data_len = 0x0, data_bufsz = 0x0}, {in_use = 
0x0, rnode = {spcNode = 0x0, dbNode = 0x0, relNode = 0x0}, forknum = 0x0, blkno 
= 0x0, flags = 0x0, has_image = 0x0, apply_image = 0x0, bkp_image = 0x0, 
hole_offset = 0x0, hole_length = 0x0,
      bimg_len = 0x0, bimg_info = 0x0, has_data = 0x0, data = 0x0, data_len = 
0x0, data_bufsz = 0x0} <repeats 29 times>}, max_block_id = 0x0, readBuf = 
0x4632868, readLen = 0x2000, readSegNo = 0x39, readOff = 0x1e8e000, readPageTLI 
= 0x1, latestPagePtr = 0xe41e8e000,
  latestPageTLI = 0x1, currRecPtr = 0xe41e8fb28, currTLI = 0x0, 
currTLIValidUntil = 0x0, nextTLI = 0x0, readRecordBuf = 0x4638888, 
readRecordBufSize = 0xa000, errormsg_buf = 0x4634878, noPayload = 0x0, 
polar_logindex_meta_size = 0x2e}
(gdb) p /x minRecoveryPoint
$11 = 0xe41bbbfd8
(gdb) p reachedConsistency
$12 = true
(gdb) p standbyState
$13 = STANDBY_SNAPSHOT_READY
(gdb) p ArchiveRecoveryRequested
$14 = true


After the crash the standby redo started from 0xDBE1241D8, and reached 
consistency at 0xE41BBBFD8 because of previous minRecoveryPoint. It did not 
repaly all WAL record after the crash.
From the crash stack we see that it was reading clog to check xid= 63800060 
status.
But in wal file we see that xid= 63800060 was first created by xlog record 
which lsn=0xE42C22D68.


rmgr: Heap        len (rec/tot):     79/    79, tx:   63800060, lsn: 
E/42C22D68, prev E/42C22D40, desc: UPDATE off 45 xmax 63800060 ; new off 56 
xmax 0, blkref #0: rel 1663/122780008/122781225 blk 14313
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C22DB8, prev E/42C22D68, desc: INSERT_LEAF off 200, blkref #0: rel 
1663/122780008/122781297 blk 2803
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C22DF8, prev E/42C22DB8, desc: INSERT_LEAF off 333, blkref #0: rel 
1663/122780008/122781313 blk 1375
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C22E38, prev E/42C22DF8, desc: INSERT_LEAF off 259, blkref #0: rel 
1663/122780008/132582066 blk 1417
rmgr: Heap        len (rec/tot):    197/   197, tx:   63800060, lsn: 
E/42C23628, prev E/42C23600, desc: HOT_UPDATE off 35 xmax 63800060 ; new off 55 
xmax 0, blkref #0: rel 1663/122780008/122781222 blk 14320
rmgr: Heap        len (rec/tot):     54/    54, tx:   63800060, lsn: 
E/42C23CF0, prev E/42C23CB0, desc: DELETE off 2 KEYS_UPDATED , blkref #0: rel 
1663/122780008/122781230 blk 14847
rmgr: Heap        len (rec/tot):    253/   253, tx:   63800060, lsn: 
E/42C260E8, prev E/42C260A8, desc: INSERT off 11, blkref #0: rel 
1663/122780008/122781230 blk 30300
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C26308, prev E/42C262C8, desc: INSERT_LEAF off 362, blkref #0: rel 
1663/122780008/122781290 blk 2925
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C266F0, prev E/42C266B0, desc: INSERT_LEAF off 369, blkref #0: rel 
1663/122780008/122781315 blk 1377
rmgr: Btree       len (rec/tot):     64/    64, tx:   63800060, lsn: 
E/42C26AE8, prev E/42C26AC0, desc: INSERT_LEAF off 308, blkref #0: rel 
1663/122780008/132498288 blk 583
rmgr: Transaction len (rec/tot):     34/    34, tx:   63800060, lsn: 
E/42C271A8, prev E/42C27168, desc: COMMIT 2020-03-16 09:56:21.540818 CST
rmgr: Heap2       len (rec/tot):     90/    90, tx:          0, lsn: 
E/4351D3A0, prev E/4351D360, desc: CLEAN remxid 63800060, blkref #0: rel 
1663/122780008/122781225 blk 14313
rmgr: Heap2       len (rec/tot):     96/    96, tx:          0, lsn: 
E/4381C898, prev E/4381C860, desc: CLEAN remxid 63800060, blkref #0: rel 
1663/122780008/122781222 blk 14320


Is it caused by inconsistency clog and data page ,like from minRecoveryPoint 
0xE41BBBFD8 to 0xE42C22D68  dirty page was flushed to the storage but clog was 
not flushed and then crashed?


BRS
Ray

Reply via email to