[MDEV-22229] InnoDB: error clustered record for sec rec not found Created: 2020-04-13  Updated: 2020-06-22  Resolved: 2020-06-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: None
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Harald Hannelius Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None


 Description   

I have gigabytes of syslog filled with this;

Apr 13 07:02:06 penti mysqld[18227]: 2020-04-13 07:02:06 7fffd95a4700 InnoDB: error clustered record for sec rec not found
Apr 13 07:02:06 penti mysqld[18227]: InnoDB: index `exptime` of table `fe83wiki`.`objectcache`
Apr 13 07:02:06 penti mysqld[18227]: InnoDB: sec index record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
Apr 13 07:02:06 penti mysqld[18227]: 0: len 8; hex 8000125f46646f73; asc _Fdos;;
Apr 13 07:02:06 penti mysqld[18227]: 1: len 30; hex 6665383377696b693a7063616368653a6964686173683a313639362d3021; asc fe83wiki:pcache:idhash:1696-0!; (total 39 bytes);
Apr 13 07:02:06 penti mysqld[18227]: InnoDB: clust index record PHYSICAL RECORD: n_fields 5; compact format; info bits 0
Apr 13 07:02:06 penti mysqld[18227]: 0: len 30; hex 6665383377696b693a7063616368653a6964686173683a313639352d3021; asc fe83wiki:pcache:idhash:1695-0!; (total 39 bytes);
Apr 13 07:02:06 penti mysqld[18227]: 1: len 6; hex 000017c750ec; asc P ;;
Apr 13 07:02:06 penti mysqld[18227]: 2: len 7; hex f700003db30110; asc = ;;
Apr 13 07:02:06 penti mysqld[18227]: 3: len 30; hex a5576d6edb3810ed6f9f8215506017a8637d388e23a7018a346ddc4d6223; asc Wmn 8 o P` c}8 # 4m Mb#; (total 1388 bytes);
Apr 13 07:02:06 penti mysqld[18227]: 4: len 8; hex 8000125f46720bd3; asc _Fr ;;
Apr 13 07:02:06 penti mysqld[18227]: TRANSACTION 429396372, ACTIVE 0 sec fetching rows
Apr 13 07:02:06 penti mysqld[18227]: mysql tables in use 1, locked 0
Apr 13 07:02:06 penti mysqld[18227]: MySQL thread id 327619, OS thread handle 0x7fffd95a4700, query id 262128533 localhost fe83wiki Sending data
Apr 13 07:02:06 penti mysqld[18227]: SELECT /* SqlBagOStuff::deleteObjectsExpiringBefore */ keyname,exptime FROM `objectcache` WHERE (exptime < '20200413035828') AND (exptime >= '2020-04-11 18:55:48') ORDER BY
exptime LIMIT 100
Apr 13 07:02:06 penti mysqld[18227]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

 Comments   
Comment by Marko Mäkelä [ 2020-04-14 ]

Can you provide the SQL statements to reproduce the error? Can you at the very least provide the table schema (SHOW CREATE TABLE) and fill in the affected version of the server?

Comment by Harald Hannelius [ 2020-04-14 ]

I'm purely guessing the SQL-command is the second to last line in the log?

+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
   `keyname` varchar(255) CHARACTER SET latin1 COLLATE latin1_bin NOT NULL 
DEFAULT '',
 
   `value` mediumblob,
 
   `exptime` datetime DEFAULT NULL,
 
   PRIMARY KEY (`keyname`),
 
   KEY `exptime` (`exptime`)
 
) ENGINE=InnoDB DEFAULT CHARSET=latin1 |
 
+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
1 row in set (0.00 sec)

Server version: 10.1.44-MariaDB-0+deb9u1 Debian 9.11

On Tue, 14 Apr 2020, Marko Mäkelä (Jira) wrote:

–
Harald Hannelius | harald@iki.fi | +358505941020

Comment by Harald Hannelius [ 2020-04-18 ]

It crashed again, starting to flood the logs. Happy I caught it this time,
before the logs fill.

Apr 18 20:36:56 penti mysqld[30357]: 
616368653a69646f7074696f6e733a31353636; asc fe2020-04-18 20:36:56 
140736988305152 [Note] /usr/sbin/mysqld: Normal shutdown
 
Apr 18 20:36:56 penti mysqld[30357]: 83wiki:pcache:idoptions:1566;;
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: clust index record PHYSICAL 
RECORD: n_fields 5; compact format; info bits 0
 
Apr 18 20:36:56 penti mysqld[30357]:  0: len 30; hex 
6665383377692020-04-18 20:36:56 7fffe23b3700  InnoDB: error clustered 
record for sec rec not found
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: index 6b693a7063`exptime` of 
table 616368653a69646f7074696f6e733a2020-04-18 20:36:56 140736988305152 
[Note] Event Scheduler: Purging the queue. 0 events
 
Apr 18 20:36:56 penti mysqld[30357]: 31353635; asc 
fe83wiki:pcache:idoptions:1565;;
 
Apr 18 20:36:56 penti mysqld[30357]:  1: len 6; hex 000026c1c084; asc   & 
;;
 
Apr 18 20:36:56 penti mysqld[30357]:  2: len 7; hex 9f00003e610110; asc 
Apr 18 20:36:56 penti mysqld[30357]:  3: len 30; hex 
458ecd0ac2301084df651fa06c621aebe6281e3c1544bdc736d040b5255b; asc E    0 
e  lb   ( < D  6 @ %[; (total 159 bytes);
 
Apr 18 20:36:56 penti mysqld[30357]:  4: len 8; hex 8000125f46bffbb0; asc 
_F   `fe83wiki`.`objectcache`
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: sec index record ;;
 
Apr 18 20:36:56 penti mysqld[30357]: PHYSICAL RECORD: n_fields 2; compact 
format; info bits 0
 
Apr 18 20:36:56 penti mysqld[30357]:  0: len 8; hex 80
 
Apr 18 20:36:56 penti mysqld[30357]: TRANSACTION 703927563, ACTIVE 0 sec 
fetching rows
 
Apr 18 20:36:56 penti mysqld[30357]: 00125f46839978; asc    mysql tables 
in use 1, locked 0
 
Apr 18 20:36:56 penti mysqld[30357]: _F MySQL thread id 22174, OS thread 
handle 0x7ffff54f1700, query id 58937778 localhost fe83wiki Sending data
 
Apr 18 20:36:56 penti mysqld[30357]: SELECT /* 
SqlBagOStuff::deleteObjectsExpiringBefore  */  keyname,exptime  FROM 
`objectcache`    WHERE (exptime < '20200418173645') AND (exptime >= 
'2020-04-11 18:55:48')  ORDER BY exptime LIMIT 100
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: Submit a detailed bug report 
to https://jira.mariadb.org/
 
Apr 18 20:36:56 penti mysqld[30357]:  x;;
 
Apr 18 20:36:56 penti mysqld[30357]:  1: len 30; hex 
6665383377696b693a7063616368653a6964686173683a313536362d3021; asc 
fe83wiki:pcache:idhash:1566-0!; (total 39 bytes);
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: clust index record PHYSICAL 
RECORD: n_fields 5; compact format; info bits 0
 
Apr 18 20:36:56 penti mysqld[30357]:  0: len 30; hex 
6665383377696b693a7063616368653a6964686173683a313536352d3021; asc 
fe83wiki:pcache:idhash:1565-0!; (total 39 bytes);
 
Apr 18 20:36:56 penti mysqld[30357]:  1: len 6; hex 000026c1c083; asc   & 
;;
 
Apr 18 20:36:56 penti mysqld[30357]:  2: len 7; hex 9e000054ae0110; asc 
T   ;;
 
Apr 18 20:36:56 penti mysqld[30357]:  3: len 30; hex 
a5576b6edb3810ee6f9d8215506017886349961d574e031469b249918711; asc  Wkn 8 
o   P`  cI  WN  i I   ; (total 1335 bytes);
 
Apr 18 20:36:56 penti mysqld[30357]:  4: len 8; hex 8000125f46bffbb0; asc 
_F   ;;
 
Apr 18 20:36:56 penti mysqld[30357]: TRANSACTION 703927565, ACTIVE 0 sec 
fetching rows
 
Apr 18 20:36:56 penti mysqld[30357]: mysql tables in use 1, locked 0
 
Apr 18 20:36:56 penti mysqld[30357]: MySQL thread id 22146, OS thread 
handle 0x7fffe23b3700, query id 58937780 localhost fe83wiki Sending data
 
Apr 18 20:36:56 penti mysqld[30357]: SELECT /* 
SqlBagOStuff::deleteObjectsExpiringBefore  */  keyname,exptime  FROM 
`objectcache`    WHERE (exptime < '20200418173508') AND (exptime >= 
'2020-04-11 18:55:48')  ORDER BY exptime LIMIT 100
 
Apr 18 20:36:56 penti mysqld[30357]: InnoDB: Submit a detailed bug report 
to https://jira.mariadb.org/

There's something with wiki's objectcache-table?

On Fri, 17 Apr 2020, Harald Hannelius wrote:

–
Harald Hannelius | harald@iki.fi | +358505941020

Comment by Harald Hannelius [ 2020-04-18 ]

I read this page; https://blog.ghost3k.net/articles/mysql/169/fixing-mysql-innodb-index-corruption

And sure enough;

MariaDB [fe83wiki]> check table objectcache;
 
 
 
+----------------------+-------+----------+--------------------------------------------------------------+
 
| Table                | Op    | Msg_type | Msg_text                                                     |
 
+----------------------+-------+----------+--------------------------------------------------------------+
 
| fe83wiki.objectcache | check | Warning  | InnoDB: Index 'exptime' contains 588 entries, should be 813. |
 
| fe83wiki.objectcache | check | error    | Corrupt                                                      |
 
+----------------------+-------+----------+--------------------------------------------------------------+
 
2 rows in set (0.06 sec)
 
 
 
MariaDB [fe83wiki]> optimize table objectcache;
 
+----------------------+----------+----------+-------------------------------------------------------------------+
 
| Table                | Op       | Msg_type | Msg_text                                                          |
 
+----------------------+----------+----------+-------------------------------------------------------------------+
 
| fe83wiki.objectcache | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
 
| fe83wiki.objectcache | optimize | status   | OK                                                                |
 
+----------------------+----------+----------+-------------------------------------------------------------------+
 
2 rows in set (0.44 sec)
 
 
 
MariaDB [fe83wiki]> check table objectcache;
 
+----------------------+-------+----------+----------+
 
| Table                | Op    | Msg_type | Msg_text |
 
+----------------------+-------+----------+----------+
 
| fe83wiki.objectcache | check | status   | OK       |
 
+----------------------+-------+----------+----------+
 
1 row in set (0.01 sec)

I'll follow up and see if this did it.

Comment by Harald Hannelius [ 2020-04-18 ]

A bigger problem is that mysqld keeps pushing info into syslog with an incredible rate. The table is 9 MB on disk, this error produced 22 GB of errorlogs in syslog in just 24 hours (which I haven't still figured out how to disable on debian).

Comment by Sergei Golubchik [ 2020-05-18 ]

Do you still see table corruption warnings?

Comment by Harald Hannelius [ 2020-05-18 ]

No warnings since.

Generated at Thu Feb 08 09:13:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.