[Info-ingres] Error on database recovery

Wed Jan 8 14:11:31 UTC 2020

Hi All,

After some work I have managed to make a small scale test case which shows this problem. It also occurs on 11.1 +p15503

The problem stems from the column being altered from an integer4 to an integer1. Sadly there was some data which exceeded the limit of an integer1 item.

The alter table alter column should have picked this up ... but didn't. Strangely this appears to be also related to the size of the table. If I do a simple test on a table with 1 row the alter table does pick up the offending integer overflow.

I'll raise an issue with Actian.

Marty

From: Martin Bowes
Sent: 08 January 2020 11:45
To: info-ingres at lists.planetingres.org
Subject: Error on database recovery

Hi All,

Fortunately this was found in a trial...

Ingres 11.0.0.

During a full database recovery rolling all journals we somewhat unexpectedly failed with the following in the errlog...

bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, ulx.c:300             ]: Wed Jan  8 08:57:14 2020 E_DM9049_UNKNOWN_EXCEPTION    An Unexpected Exception occurred in the DMF Facility, exception number 68196.
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, ulx.c:320             ]: Wed Jan  8 08:57:14 2020 E_UL0306_EXCEPTION    Unexpected exception number 68196 occurred, but unable to determine the type.
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:5273         ]: Wed Jan  8 08:57:14 2020 E_DM004A_INTERNAL_ERROR   Internal DMF error detected.
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:3526         ]: Wed Jan  8 08:57:14 2020 E_DM1306_RFP_APPLY_RECORD Error occurred attempting to apply rollforward record.
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO         LSN=(000000005B3CCEAD,00000000ECEB6643), COMP_LSN=(0000000000000000,0000000000000000), DBID=0x0585CD6D, XID=0x00005B3D355D8E
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO 0D
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO         MODIFY       Length:  2520  Flags: JOURNAL,NONREDO
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO             TABLE: (2512,0) NAME(bulk_master,ace)
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO             STRUCTURE: BTREE STATUS: UNIQUE,DUPLICATES
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO             MINPAGES: 0 MAXPAGES: 0 IFILL: 80 DFILL: 80 LFILL: 70
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO             BUCKETS: 32598  RELTUPS: 5036857
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO             Alloc: 4  Extend: 16  Page size: 8192 Type: 70  Name: (2, 371439)
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO                 LOCATION: ii_database
bba.ctsu.ox.ac.uk ::[II_JSP            , 33449     ,  00007f15084fa200, dmfrfp.c:14586        ]: Wed Jan  8 08:57:14 2020 E_DM1371_RFP_INFO Open Transaction 0x00005B3D355D8E0D with BT time 04-Jan-2020 15:29:53.73 for database ace_trexy_live redo 9 undo 0

etc...

With errors E_DM9C5F_DM2T_PURGEBUSY_WARN, E_DM9C53_DM2T_UNFIX_TCB, E_DM9330_DM2T_PURGE_TCB...

Examination of the audit trail shows that the relevant transaction:

Begin   : Transaction Id 00005b3d355d8e0d 04-Jan-2020 15:29:53.73           Username ace

  Alter   : Transaction Id 00005b3d355d8e0d Id (2512,0) Table [bulk_master                     ,ace                             ]

  Modify  : Transaction Id 00005b3d355d8e0d Id (2512,0) Table [bulk_master                     ,ace                             ]

  Drop/Destroy : Transaction Id 00005b3d355d8e0d Id (2512,5057)     Table [bulk_master_fields              ,ace

                     ]

    Location ii_database

  Create  : Transaction Id 00005b3d355d8e0d Id (2512,6099)      Table [bulk_master_fields              ,ace

                ]

    Location ii_database

Begin   : Transaction Id 00005b3d355d90f3 04-Jan-2020 15:30:07.56           Username ace

End     : Transaction Id 00005b3d355d90f3 04-Jan-2020 15:30:07.58

  Index   : Transaction Id 00005b3d355d8e0d  Id (2512,6099) Table [bulk_master                     ,ace

                ]

End     : Transaction Id 00005b3d355d8e0d 04-Jan-2020 15:30:08.26

The table alteration was to change a column from integer4 to integer1.

The audit trail says the transaction was well and truly closed

I've been unable to reproduce this with a small test case...and the thought of pushing a several hundred gig backup and journals to Actian isn't thrilling me...Has anyone seen anything like this? Got any ideas?

Martin Bowes

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.planetingres.org/pipermail/info-ingres/attachments/20200108/163f37af/attachment.html>