Thread: could not access status of transaction

In our PG 10.2(CentOS 7.3) database, the following error is reported when querying a table. We have already restored
theproduction data through backup, but i want to confirm what may be the reason and how to avoid it in the future. 

    lma=# select count(*) from bi_dm.tdm_ttk_site_on_way_rt;
    ERROR:  could not access status of transaction 3250922107
    DETAIL:  Could not open file "pg_xact/0C1C": No such file or directory.

Here are some related information

The CLOG files in pg_xact diractory is as follow:

    0C4A(Last update date: 2018/12/29)
        ...
        0D09(Last update date: 2019/01/13)

The stack when the error occurs is as follows

    (gdb) bt
    #0  SlruReportIOError (ctl=ctl@entry=0xca98e0 <ClogCtlData>, pageno=pageno@entry=99210, xid=xid@entry=3250922107)
atslru.c:901 
    #1  0x00000000004e53a8 in SimpleLruReadPage (ctl=ctl@entry=0xca98e0 <ClogCtlData>, pageno=pageno@entry=99210,
write_ok=write_ok@entry=1'\001', xid=xid@entry=3250922107) 
        at slru.c:445
    #2  0x00000000004e5460 in SimpleLruReadPage_ReadOnly (ctl=ctl@entry=0xca98e0 <ClogCtlData>,
pageno=pageno@entry=99210,xid=xid@entry=3250922107) at slru.c:492 
    #3  0x00000000004dde4d in TransactionIdGetStatus (xid=xid@entry=3250922107, lsn=lsn@entry=0x7ffeb4472660) at
clog.c:411
    #4  0x00000000004e6e28 in TransactionLogFetch (transactionId=3250922107) at transam.c:79
    #5  0x00000000004e6e7f in TransactionIdDidCommit (transactionId=<optimized out>) at transam.c:129
    #6  0x000000000084ce6a in HeapTupleSatisfiesMVCC (htup=<optimized out>, snapshot=0xf7f0c8, buffer=837) at
tqual.c:1124
    #7  0x00000000004b106e in heapgetpage (scan=scan@entry=0x10bb1b0, page=page@entry=1078209) at heapam.c:439
    #8  0x00000000004b23ab in heapgettup_pagemode (key=0x0, nkeys=0, dir=1078209, scan=0x10bb1b0) at heapam.c:1034
    #9  heap_getnext (scan=scan@entry=0x10bb1b0, direction=direction@entry=ForwardScanDirection) at heapam.c:1801
    #10 0x000000000060fa93 in SeqNext (node=node@entry=0x108c360) at nodeSeqscan.c:81
    #11 0x00000000005f51ca in ExecScanFetch (recheckMtd=0x60fa40 <SeqRecheck>, accessMtd=0x60fa60 <SeqNext>,
node=0x108c360)at execScan.c:97 
    #12 ExecScan (node=0x108c360, accessMtd=0x60fa60 <SeqNext>, recheckMtd=0x60fa40 <SeqRecheck>) at execScan.c:147
    #13 0x00000000005fad89 in ExecProcNode (node=0x108c360) at ../../../src/include/executor/executor.h:250
    #14 fetch_input_tuple (aggstate=aggstate@entry=0x108bcb8) at nodeAgg.c:695
    #15 0x00000000005fcdbf in agg_retrieve_direct (aggstate=0x108bcb8) at nodeAgg.c:2448
    #16 ExecAgg (pstate=0x108bcb8) at nodeAgg.c:2158
    #17 0x00000000005ef612 in ExecProcNode (node=0x108bcb8) at ../../../src/include/executor/executor.h:250
    #18 ExecutePlan (execute_once=<optimized out>, dest=0x10c40e8, direction=<optimized out>, numberTuples=0,
sendTuples=1'\001', operation=CMD_SELECT,  
        use_parallel_mode=<optimized out>, planstate=0x108bcb8, estate=0x108baa8) at execMain.c:1722
    #19 standard_ExecutorRun (queryDesc=0x10c7168, direction=<optimized out>, count=0, execute_once=<optimized out>) at
execMain.c:363
    #20 0x00007f766427915d in pgss_ExecutorRun (queryDesc=0x10c7168, direction=ForwardScanDirection, count=0,
execute_once=<optimizedout>) at pg_stat_statements.c:889 
    #21 0x000000000071a28b in PortalRunSelect (portal=portal@entry=0xfac708, forward=forward@entry=1 '\001', count=0,
count@entry=9223372036854775807,dest=dest@entry=0x10c40e8) 
        at pquery.c:932
    #22 0x000000000071b63f in PortalRun (portal=portal@entry=0xfac708, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1'\001',  
        run_once=run_once@entry=1 '\001', dest=dest@entry=0x10c40e8, altdest=altdest@entry=0x10c40e8,
completionTag=completionTag@entry=0x7ffeb4472c80"") at pquery.c:773 
    #23 0x00000000007175b3 in exec_simple_query (query_string=0x102a4e8 "select count(*) from tdm_ttk_site_on_way_rt
;")at postgres.c:1099 
    #24 0x00000000007188ac in PostgresMain (argc=<optimized out>, argv=argv@entry=0xfa2d68, dbname=0xfa2c50 "lma",
username=<optimizedout>) at postgres.c:4088 
    #25 0x000000000047ad3c in BackendRun (port=0xfa49b0) at postmaster.c:4405
    #26 BackendStartup (port=0xfa49b0) at postmaster.c:4077
    #27 ServerLoop () at postmaster.c:1755
    #28 0x00000000006afacf in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0xf5fa20) at postmaster.c:1363
    #29 0x000000000047bb6f in main (argc=3, argv=0xf5fa20) at main.c:228
    (gdb) f 6
    #6  0x000000000084ce6a in HeapTupleSatisfiesMVCC (htup=<optimized out>, snapshot=0xf7f0c8, buffer=837) at
tqual.c:1124
    1124                    if (!TransactionIdDidCommit(HeapTupleHeaderGetRawXmax(tuple)))
    (gdb) p *tuple
    $3 = {t_choice = {t_heap = {t_xmin = 3238223060, t_xmax = 3250922107, t_field3 = {t_cid = 0, t_xvac = 0}}, t_datum
={datum_len_ = -1056744236, datum_typmod = -1044045189,  
          datum_typeid = 0}}, t_ctid = {ip_blkid = {bi_hi = 16, bi_lo = 29633}, ip_posid = 3}, t_infomask2 = 8211,
t_infomask= 258, t_hoff = 24 '\030',  
      t_bits = 0x7f666297141f ""}

That is, when reading a record with ctid of (1078209, 3), the tuple in page 1078209 is as follows:

    lma=# select * from  heap_page_items(get_raw_page('bi_dm.tdm_ttk_site_on_way_rt',1078209));
     lp | lp_off | lp_flags | lp_len |   t_xmin   |   t_xmax   | t_field3 |    t_ctid    | t_infomask2 | t_infomask |
t_hoff| t_bits | t_oid | t_data 

----+--------+----------+--------+------------+------------+----------+--------------+-------------+------------+--------+--------+-------+-----------
      1 |   8024 |        1 |    168 | 3238223060 | 3250922107 |        0 | (1078209,1)  |        8211 |       1282 |
 24 |        |       | \x...... 
      2 |   7864 |        1 |    156 | 3238223060 | 3250922107 |        0 | (1078209,2)  |        8211 |       1282 |
 24 |        |       | \x...... 
      3 |   7688 |        1 |    176 | 3238223060 | 3250922107 |        0 | (1078209,3)  |        8211 |        258 |
 24 |        |       | \x...... 
      4 |   7536 |        1 |    152 | 3238223060 | 3250922107 |        0 | (1078209,4)  |        8211 |        258 |
 24 |        |       | \x...... 
      5 |   7368 |        1 |    164 | 3238223060 | 3250922107 |        0 | (1078209,5)  |        8211 |        258 |
 24 |        |       | \x...... 
      6 |   7192 |        1 |    176 | 3238223060 | 3250922107 |        0 | (1078209,6)  |        8211 |        258 |
 24 |        |       | \x...... 
      7 |   7016 |        1 |    176 | 3238223060 | 3250922107 |        0 | (1078209,7)  |        8211 |        258 |
 24 |        |       | \x...... 
    ...

t_infomask of the record after the third one above is different from the first two. The HEAP_XMAX_COMMITTED flag is set
inthe first two t_infomasks (1282).This means that transaction 3250922107 has been submitted. 


The relevant configuration of the database is as follows:

    lma=# show autovacuum_freeze_max_age ;
     autovacuum_freeze_max_age
    ---------------------------
     200000000
    (1 row)

    lma=# select relfrozenxid from pg_class where relname='tdm_ttk_site_on_way_rt';
    relfrozenxid
    --------------
       3424813835
    (1 row)

    lma=# select txid_current();
    txid_current
    --------------
      24957915753
    (1 row)

    lma=#
    lma=# create table tb1(id int);
    CREATE TABLE
    lma=# insert into tb1 values(1);
    INSERT 0 1
    lma=# select xmin from tb1;
        xmin
    ------------
    3483079275
    (1 row)


A similar problem has been reported in 9.0, but there is no reason to mention it.

https://www.postgresql.org/message-id/flat/1300970362.2349.27.camel%40stevie


Currently I suspect that it may be the same problem as the bug below. is it possible?

The bug will cause some sessions to cache the wrong relfrozenxid of the table. The session that may call
vac_truncate_clog()will clean up the clog after the actual relfrozenxid due to reading the wrong relfrozenxid. 

https://www.postgresql.org/message-id/flat/20180809161148.GB22623%40momjian.us#a7cc4d41464064b7752a5574eb74a06d

Regards,
Chen Huajun

On 1/20/19 5:07 PM, chenhj wrote:
> In our PG 10.2(CentOS 7.3) database, the following error is reported when querying a table. We have already restored
theproduction data through backup, but i want to confirm what may be the reason and how to avoid it in the future.
 
> 
>     lma=# select count(*) from bi_dm.tdm_ttk_site_on_way_rt;
>     ERROR:  could not access status of transaction 3250922107
>     DETAIL:  Could not open file "pg_xact/0C1C": No such file or directory.
> 
> Here are some related information
> 
> The CLOG files in pg_xact diractory is as follow:
> 
>     0C4A(Last update date: 2018/12/29)
>         ...
>         0D09(Last update date: 2019/01/13)
> 

Yes, that very much looks like a data corruption, probably due to
truncating the clog too early or something like that.

> ...
> 
> A similar problem has been reported in 9.0, but there is no reason to mention it.
> 
> https://www.postgresql.org/message-id/flat/1300970362.2349.27.camel%40stevie
> 

The symptoms are the same, but that's far from sufficient to conclude
it's the same root cause.

> Currently I suspect that it may be the same problem as the bug below. is it possible?
> 
> The bug will cause some sessions to cache the wrong relfrozenxid of the table. The session that may call
vac_truncate_clog()will clean up the clog after the actual relfrozenxid due to reading the wrong relfrozenxid.
 
> 
> https://www.postgresql.org/message-id/flat/20180809161148.GB22623%40momjian.us#a7cc4d41464064b7752a5574eb74a06d
> 

Maybe. But it'll be hard to confirm it's what happened. It also shows
why it's important to keep up with minor updates (you're running 10.3,
which is almost 1 year old).

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Sun, Jan 5, 2020 at 11:00 PM chenhj <chjischj@163.com> wrote:
> According to above information, the flags of the heap page (163363) with the problem tuple (163363, 9) is 0x0001
(HAS_FREE_LINES),that is, ALL_VISIBLE is not set.
 
>
> However, according  hexdump content of the corresponding vm file, that block(location is 9F88 + 6bit) has set
VISIBILITYMAP_ALL_FROZENand VISIBILITYMAP_ALL_VISIBLE flags. That is, the heap file and the vm file are inconsistent.
 

That's not supposed to happen, and represents data corruption. Your
previous report of a too-old xmin surviving in the heap is also
corruption.  There is no guarantee that both problems have the same
cause, but suppose they do. One possibility is that a write to the
heap page may have gotten lost or undone. Suppose that, while this
page was in shared_buffers, VACUUM came through and froze it, setting
the bits in the VM and later truncating CLOG. Then, suppose that when
that page was evicted from shared_buffers, it didn't really get
written back to disk, or alternatively it did, but then later somehow
the old version reappeared. I think that would produce these symptoms.

I think that bad hardware could cause this, or running two copies of
the server on the same data files at the same time, or maybe some kind
of filesystem-related flakiness, especially if, for example, you are
using a network filesystem like NFS, or maybe a broken iSCSI stack.
There is also no reason it couldn't be a bug in PostgreSQL itself,
although if we lost page writes routinely somebody would surely have
noticed by now.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company