Re: crash 11.5~ (and 11.4)

On Wed, Aug 07, 2019 at 04:51:54PM -0700, Andres Freund wrote:
> Hi,
> 
> On 2019-08-07 14:29:28 -0500, Justin Pryzby wrote:
> > Just found this, although I'm not sure what to do about it.  If it's corrupt
> > table data, I can restore from backup.

In the meantime, I've renamed+uninherited the table and restored from backup,
with the broken table preserved.

However, the previous days' backup did this, so I used Monday's backup.

[pryzbyj@database ~]$ time sudo -u postgres pg_restore /srv/cdrperfbackup/ts/2019-08-06/curtables/ -t
huawei_umts_ucell_201908--verbose -d ts --host /tmp
 
pg_restore: connecting to database for restore
pg_restore: creating TABLE "child.huawei_umts_ucell_201908"
pg_restore: INFO:  partition constraint for table "huawei_umts_ucell_201908" is implied by existing constraints
pg_restore: processing data for table "child.huawei_umts_ucell_201908"
pg_restore: [archiver (db)] Error while PROCESSING TOC:
pg_restore: [archiver (db)] Error from TOC entry 62710; 0 2015128626 TABLE DATA huawei_umts_ucell_201908 telsasoft
pg_restore: [archiver (db)] COPY failed for table "huawei_umts_ucell_201908": ERROR:  invalid byte sequence for
encoding"UTF8": 0xe7 0x28 0x9d
 
CONTEXT:  COPY huawei_umts_ucell_201908, line 104746

Also, I found core with this BT from my own manual invocation of ANALYZE.

(gdb) bt
#0  0x00000039674324f5 in raise () from /lib64/libc.so.6
#1  0x0000003967433cd5 in abort () from /lib64/libc.so.6
#2  0x0000000000a3c4b2 in ExceptionalCondition (conditionName=0xaad9e7 "!(j > attnum)", errorType=0xaad84c
"FailedAssertion",fileName=0xaad840 "heaptuple.c", lineNumber=582) at assert.c:54
 
#3  0x00000000004856a7 in nocachegetattr (tuple=0x1c116b08, attnum=1, tupleDesc=0x23332b0) at heaptuple.c:582
#4  0x000000000062981d in std_fetch_func (stats=0x22700c8, rownum=54991, isNull=0x7ffff5f3844f) at analyze.c:1718
#5  0x000000000062aa99 in compute_scalar_stats (stats=0x22700c8, fetchfunc=0x62942b <std_fetch_func>,
samplerows=120000,totalrows=227970) at analyze.c:2370
 
#6  0x00000000006270db in do_analyze_rel (onerel=0x7fd37e2afa50, options=2, params=0x7ffff5f38a70, va_cols=0x0,
acquirefunc=0x627e9e<acquire_sample_rows>, relpages=75494, inh=false,
 
    in_outer_xact=false, elevel=13) at analyze.c:579
#7  0x0000000000626616 in analyze_rel (relid=2015128626, relation=0x2161820, options=2, params=0x7ffff5f38a70,
va_cols=0x0,in_outer_xact=false, bstrategy=0x21f7848) at analyze.c:310
 
#8  0x00000000006c59b2 in vacuum (options=2, relations=0x21f79c0, params=0x7ffff5f38a70, bstrategy=0x21f7848,
isTopLevel=true)at vacuum.c:357
 
#9  0x00000000006c54e0 in ExecVacuum (vacstmt=0x2161910, isTopLevel=true) at vacuum.c:141
#10 0x00000000008d1d7e in standard_ProcessUtility (pstmt=0x21619d0, queryString=0x2160d28 "ANALYZE child.
huawei_umts_ucell_201908;",context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
 
    dest=0x2161cc0, completionTag=0x7ffff5f39100 "") at utility.c:670

#3  0x00000000004856a7 in nocachegetattr (tuple=0x1c116b08, attnum=1, tupleDesc=0x23332b0) at heaptuple.c:582
        natts = 554
        j = 1
        tup = 0x1c116b20
        tp = 0x1c116b85
"\374\023\026\213^s#\347(\235=\326\321\067\032\245\321B\026}܋FS\375\244\003\065\336\277;\252O\006\065\320\353\211}F\237\373B\243\357J~\270\"\230ƣ\024xǍ\334\377\202\277S\031\375\351\003\220{\004"
        bp = 0x1c116b37
"\270\027$U}\232\246\235\004\255\331\033\006Qp\376E\316h\376\363\247\366Նgy7\311E\224~F\274\023ϋ%\216,\221\331@\024\363\233\070\275\004\254L\217t\262X\227\352\346\347\371\070\321ш\221\350fc\316\r\356\351h\275\213\230\360\203\374\023\026\213^s#\347(\235=\326\321\067\032\245\321B\026}܋FS\375\244\003\065\336\277;\252O\006\065\320\353\211}F\237\373B\243\357J~\270\"\230ƣ\024xǍ\334\377\202\277S\031\375\351\003\220{\004"
        slow = false
        off = -1
#4  0x000000000062981d in std_fetch_func (stats=0x22700c8, rownum=54991, isNull=0x7ffff5f3844f) at analyze.c:1718
        attnum = 2
        tuple = 0x1c116b08
        tupDesc = 0x23332b0
#5  0x000000000062aa99 in compute_scalar_stats (stats=0x22700c8, fetchfunc=0x62942b <std_fetch_func>,
samplerows=120000,totalrows=227970) at analyze.c:2370
 
        value = 546120480
        isnull = false
        i = 54991
        null_cnt = 0
        nonnull_cnt = 54991
        toowide_cnt = 0
---Type <return> to continue, or q <return> to quit---
        total_width = 274955
        is_varlena = true
        is_varwidth = true
        corr_xysum = 3.9525251667299724e-323
        ssup = {ssup_cxt = 0x22ae080, ssup_collation = 100, ssup_reverse = false, ssup_nulls_first = false, ssup_attno
=0, ssup_extra = 0x22ae5b0, comparator = 0xa06720 <varstrfastcmp_locale>,
 
          abbreviate = false, abbrev_converter = 0, abbrev_abort = 0, abbrev_full_comparator = 0}
        values = 0x204f9970
        values_cnt = 54991
        tupnoLink = 0x206ce5c0
        track = 0x22ae198
        track_cnt = 0
        num_mcv = 100
        num_bins = 100
        mystats = 0x2270490

> > ts=# VACUUM FREEZE VERBOSE child.huawei_umts_ucell_201908;
> > INFO:  00000: aggressively vacuuming "child.huawei_umts_ucell_201908"
> > LOCATION:  lazy_scan_heap, vacuumlazy.c:502
> > ERROR:  XX001: found xmin 73850277 from before relfrozenxid 111408920
> > LOCATION:  heap_prepare_freeze_tuple, heapam.c:6853
> 
> Ugh :(
> 
> We really need to add a error context to vacuumlazy that shows which
> block is being processed.

> > I confirmed I updated to 11.4 immediately on its release:
> > [pryzbyj@database ~]$ ls -ltc /usr/pgsql-11/bin/postgres
> > -rwxr-xr-x. 1 root root 7291736 Jun 20 07:09 /usr/pgsql-11/bin/postgres
> 
> Any chance you might not have restarted postgres at that time?

I don't think so, nagios would've been yelling at me.  Also..I found I have a
log of pg_settings, which shows server_version updated 2019-06-20
07:05:01.425645.  Is there a bug in 11.3 which could explain it ?

> > Here's usable looking bt
> > 
> > #0  heap_prepare_freeze_tuple (tuple=0x7fd3d8fa0058, relfrozenxid=111408920, 
> >     relminmxid=1846, cutoff_xid=111658731, cutoff_multi=1846, frz=0x223e930, 
> >     totally_frozen_p=0x7ffff5f3848f) at heapam.c:6832
> >         changed = 211
> >         xmax_already_frozen = 127
> >         xmin_frozen = false
> >         freeze_xmax = false
> >         xid = 0
> >         __func__ = "heap_prepare_freeze_tuple"
> 
> Hm. That's a backtrace to what precisely? Are you sure it's the the
> erroring call to heap_prepare_freeze_tuple? Because I think that's at
> the function's start - which is why some of the stack variables have
> bogus contents.

Yes, I had just done this: b heap_prepare_freeze_tuple.

> I think you'd need to set the breakpoint to heapam.c:6850 to be sure to
> catch the error (while the error message heapam.c:6853, that's because
> the line macro in some compilers expands to the end of the statement).

I did 6848 and got;

#0  heap_prepare_freeze_tuple (tuple=0x7fd403a02058, relfrozenxid=111408920, relminmxid=1846, cutoff_xid=111665057,
cutoff_multi=1846,frz=0x22aa6f8, totally_frozen_p=0x7ffff5f3848f) at heapam.c:6849
 
        changed = false
        xmax_already_frozen = false
        xmin_frozen = false
        freeze_xmax = false
        xid = 73850277
        __func__ = "heap_prepare_freeze_tuple"

> > errfinish one seems to be not useful?
> > 
> > (gdb) bt
> > #0  errfinish (dummy=0) at elog.c:415
> > #1  0x000000000054aefd in ShowTransactionStateRec (
> >     str=0xafed12 "StartTransaction", s=0xf9efa0) at xact.c:5157
> > [...]
>
> That's probably just the errfinish for a debug message. Might be easier
> to set a breakpoint to pg_re_throw().

Right, that works.

(gdb) bt
#0  pg_re_throw () at elog.c:1730
#1  0x0000000000a3cb1e in errfinish (dummy=0) at elog.c:467
#2  0x00000000004e72c4 in heap_prepare_freeze_tuple (tuple=0x7fd403a02058, relfrozenxid=111408920, relminmxid=1846,
cutoff_xid=111665065,cutoff_multi=1846, frz=0x2260558, totally_frozen_p=0x7ffff5f3848f) at heapam.c:6850
 
#3  0x00000000006c8e6e in lazy_scan_heap (onerel=0x7fd37d5f99c8, options=13, vacrelstats=0x22603b8, Irel=0x2260500,
nindexes=3,aggressive=true) at vacuumlazy.c:1151 

> > I looked at this briefly:
> > 
> > ts=# SELECT * FROM page_header(get_raw_page('child.huawei_umts_ucell_201908', 0));
> > lsn       | 3A49/66F44310
> > checksum  | 0
> > flags     | 4
> > lower     | 36
> > upper     | 1432
> > special   | 8192
> > pagesize  | 8192
> > version   | 4
> > prune_xid | 0
> 
> That's not necessarily the target block though, right?  It'd be useful
> to get this for the block with the corruption, and perhaps one
> before/after.  If the backtrace I commented on at the top is correct,
> the relevant tuple was at "blkno = 34915" (visible a frame or two
> up).

Ah, right.

ts=# SELECT * FROM page_header(get_raw_page('child.huawei_umts_ucell_201908', 34914));
      lsn      | checksum | flags | lower | upper | special | pagesize | version | prune_xid 
---------------+----------+-------+-------+-------+---------+----------+---------+-----------
 3A4A/4F2192B8 |        0 |     0 |    36 |  1520 |    8192 |     8192 |       4 |         0

ts=# SELECT * FROM page_header(get_raw_page('child.huawei_umts_ucell_201908', 34915));
 3A4A/4F21C268 |        0 |     0 |    36 |  1520 |    8192 |     8192 |       4 |         0

ts=# SELECT * FROM page_header(get_raw_page('child.huawei_umts_ucell_201908', 34916));
 3A4A/4F21DC90 |        0 |     0 |    36 |  1496 |    8192 |     8192 |       4 |         0

> Also heap_page_items() for those pages would be useful - you might want
> to not include the t_data column, as it has raw tuple data.

ts=# SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax, t_field3, t_ctid, t_infomask2, t_infomask, t_hoff, t_bits,
t_oidFROM heap_page_items(get_raw_page('child.huawei_umts_ucell_201908', 34914));
 
 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 
 

  1 |   5952 |        1 |   2236 | 111659903 |      0 |        0 | (34914,1) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000001111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111001111111111111111111111011111111111111111011111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  2 |   3736 |        1 |   2212 | 111659903 |      0 |        0 | (34914,2) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111100000000011111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111000111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  3 |   1520 |        1 |   2216 | 111659903 |      0 |        0 | (34914,3) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111100000001011111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111000111111111111111111111011111111111111111011111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 

ts=# SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax, t_field3, t_ctid, t_infomask2, t_infomask, t_hoff, t_bits,
t_oidFROM heap_page_items(get_raw_page('child.huawei_umts_ucell_201908', 34915));
 
  1 |   5976 |        1 |   2212 | 111659903 |      0 |        0 | (34915,1) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111100000001011111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111000111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  2 |   3744 |        1 |   2232 | 111659903 |      0 |        0 | (34915,2) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111100001111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111001111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  3 |   1520 |        1 |   2220 | 111659903 |      0 |        0 | (34915,3) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000001011111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111000111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 

ts=# SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax, t_field3, t_ctid, t_infomask2, t_infomask, t_hoff, t_bits,
t_oidFROM heap_page_items(get_raw_page('child.huawei_umts_ucell_201908', 34916));
 
  1 |   5952 |        1 |   2236 | 111659903 |      0 |        0 | (34916,1) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000001111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111001111111111111111111111011111111111111111011111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  2 |   3736 |        1 |   2212 | 111659903 |      0 |        0 | (34916,2) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111100000001011111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111000111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000001111111111111111111111111111111111111111111100111111000000
|     
 
  3 |   1496 |        1 |   2240 | 111659903 |      0 |        0 | (34916,3) |         554 |       2311 |     96 |
11111111111111111111111111111111111111011100111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111000001111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001111111111111111111111001111111111111111111111011111111111111111010111111101101111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111001100000001111111111111111111111111111111111111111111100111111000000
|      
> Could you show
> * pg_controldata

[pryzbyj@database ~]$ sudo -u postgres ./src/postgresql.bin/bin/pg_controldata -D /var/lib/pgsql/11/data
[sudo] password for pryzbyj:
pg_control version number:            1100
Catalog version number:               201809051
Database system identifier:           6616072377454496350
Database cluster state:               in production
pg_control last modified:             Wed 07 Aug 2019 06:32:05 PM MDT
Latest checkpoint location:           3A4C/D1BB5BD8
Latest checkpoint's REDO location:    3A4C/CCC1DF90
Latest checkpoint's REDO WAL file:    0000000100003A4C000000CC
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:111664949
Latest checkpoint's NextOID:          2069503852
Latest checkpoint's NextMultiXactId:  1846
Latest checkpoint's NextMultiOffset:  3891
Latest checkpoint's oldestXID:        33682470
Latest checkpoint's oldestXID's DB:   16564
Latest checkpoint's oldestActiveXID:  111664945
Latest checkpoint's oldestMultiXid:   1484
Latest checkpoint's oldestMulti's DB: 16564
Latest checkpoint's oldestCommitTsXid:0
Latest checkpoint's newestCommitTsXid:0
Time of latest checkpoint:            Wed 07 Aug 2019 06:31:35 PM MDT
Fake LSN counter for unlogged rels:   0/1
Minimum recovery ending location:     0/0
Min recovery ending loc's timeline:   0
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    replica
wal_log_hints setting:                off
max_connections setting:              200
max_worker_processes setting:         8
max_prepared_xacts setting:           0
max_locks_per_xact setting:           128
track_commit_timestamp setting:       off
Maximum data alignment:               8
Database block size:                  8192
Blocks per segment of large relation: 131072
WAL block size:                       8192
Bytes per WAL segment:                16777216
Maximum length of identifiers:        64
Maximum columns in an index:          32
Maximum size of a TOAST chunk:        1996
Size of a large-object chunk:         2048
Date/time type storage:               64-bit integers
Float4 argument passing:              by value
Float8 argument passing:              by value
Data page checksum version:           0
Mock authentication nonce:            ff863744b99b849579d561c5117157c78a8ced0563df824f3035f70810fec534

> * SELECT oid, datname, datfrozenxid, datminmxid FROM pg_database;
ts=# SELECT oid, datname, datfrozenxid, datminmxid FROM pg_database;
  oid  |  datname  | datfrozenxid | datminmxid 
-------+-----------+--------------+------------
 13529 | template0 |    103564559 |       1846
 16400 | template1 |     52362404 |       1486
 16443 | postgres  |     46060229 |       1485
 16564 | ts        |     33682470 |       1484
(4 rows)

> That should be easy to redact if necessary. It'd be useful to know which
> database the corrupted table is in.
> 
> It'd also be helpful to get something roughly like
> SELECT oid, oid::regclass, relkind, reltoastrelid, relfrozenxid, age(relfrozenxid), relminmxid, mxid_age(relminmxid),
relpages,(SELECT txid_current()) FROM pg_class WHERE relfrozenxid <> 0;
 

> But I'm not sure if including the tablenames would be a problematic for
> your case. Possibly a bit hard to infer "usage" correlations without,
> but probably still worthwhile.

I'll send to you individually, I don't think it's secret, but it's 60k lines
long...  Its OID verifies to me that the table was created on 8/1, and not 7/1,
which was possible.  Week-old backup also verifies that.

Thanks,
Justin