MySQL Bugs: #37364: InnoDB: error in sec index entry update

Bug #37364	InnoDB: error in sec index entry update
Submitted:	12 Jun 2008 12:52	Modified:	7 Nov 2015 7:30
Reporter:	Michael Koloberdin	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.0.51a, 5.5.21	OS:	Linux (Linux ES release 4)
Assigned to:	Heikki Tuuri	CPU Architecture:	Any

Description:
Occasionally I'm getting error messages like quoted below (#1). Apparently it later results in dieing (actually it loops restarting) of mysqld with a nasty error message (see sample #2) about page corruption.
Restarting with innodb_force_recovery=1 in my.cnf fixes the problem for some time (with or without dumping/restoring the relevant table).

Message sample #1:
-------------------------------------------------------------
InnoDB: error in sec index entry update in
InnoDB: index `timestamp` of table `my_database/geostats`
InnoDB: tuple DATA TUPLE: 3 fields;
 0: len 4; hex 484cf5a4; asc HL  ;; 1: len 5; hex 50482d4439; asc PH-D9;; 2: len 8; hex 6e6f64652f313439; asc node/149;;

InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 4; hex 484cf5a4; asc HL  ;; 1: len 2; hex 4132; asc A2;; 2: len 10; hex 6e6f64652f3438333938; asc node/48398;;

TRANSACTION 0 420179137, ACTIVE 1 sec, process no 2695, OS thread id 1168308576 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
2 lock struct(s), heap size 368, undo log entries 1
MySQL thread id 542206, query id 7491324 localhost my_database Updating
UPDATE geostats SET daycount = daycount + 1, totalcount = totalcount + 1, timestamp = 1213241280 WHERE area = 'PH-D9' AND path = 'node/149'

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
-------------------------------------------------------------

Message sample #2 (text in <<>> added by me):
-------------------------------------------------------------
080611 07:22:20  mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 6 74664612
080611  7:22:21  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 6 79907328
InnoDB: Doing recovery: scanned up to log sequence number 6 84482185
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 0 413242112
080611  7:22:22  InnoDB: Starting an apply batch of log records to the database.
..
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19
20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7
3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
080611  7:22:40  InnoDB: Started; log sequence number 6 84482185
InnoDB: Starting in background the rollback of uncommitted transactions
080611  7:22:40  InnoDB: Rolling back trx with id 0 413241705, 1 rows to undo
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 39266.
InnoDB: You may have to recover from a backup.
080611  7:22:40  InnoDB: Page dump in ascii and hex (16384 bytes):
 len 16384; hex << beginning of dump skipped, then the following message appears in the middle of the dump: >>   7:22:40 [Not
e] /usr/sbin/mysqld: ready for connections.
Version: '5.0.51a-community'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  M
ySQL Community Edition (GPL) << continuation of dump skipped >> ;InnoD
B: End of page dump
080611  7:22:40  InnoDB: Page checksum 4156272479, prior-to-4.0.14-form checksum
 3817166090
InnoDB: stored checksum 1948179423, prior-to-4.0.14-form stored checksum 3817166
090
InnoDB: Page lsn 6 68953143, low 4 bytes of lsn at page end 68953143
InnoDB: Page number (if stored to page already) 39266,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 0
InnoDB: Page may be an index page where index id is 0 139
InnoDB: (index timestamp of table mynicespace/geostats)
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 39266.
InnoDB: You may have to recover from a backup.
InnoDB: It is also possible that your operating
InnoDB: system has corrupted its own file cache
InnoDB: and rebooting your computer removes the
InnoDB: error.
InnoDB: If the corrupt page is an index page
InnoDB: you can also try to fix the corruption
InnoDB: by dumping, dropping, and reimporting
InnoDB: the corrupt table. You can use CHECK
InnoDB: TABLE to scan your table for corruption.
InnoDB: See also InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery
.html
InnoDB: about forcing recovery.
InnoDB: Ending processing because of a corrupt database page.

Number of processes running now: 0
080611 07:22:40  mysqld restarted
-------------------------------------------------------------

mysql> desc geostats;
+------------+-----------------------+------+-----+---------+-------+
| Field      | Type                  | Null | Key | Default | Extra |
+------------+-----------------------+------+-----+---------+-------+
| area       | varchar(5)            | NO   | PRI |         |       |
| path       | varchar(100)          | NO   | PRI |         |       |
| nid        | int(10) unsigned      | YES  | MUL | NULL    |       |
| totalcount | bigint(20) unsigned   | NO   | MUL | 0       |       |
| daycount   | mediumint(8) unsigned | NO   | MUL | 0       |       |
| timestamp  | int(11) unsigned      | NO   | MUL | 0       |       |
+------------+-----------------------+------+-----+---------+-------+
6 rows in set (0.02 sec)

mysql> show index from geostats;
+----------+------------+------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| Table    | Non_unique | Key_name   | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment |
+----------+------------+------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| geostats |          0 | PRIMARY    |            1 | area        | A         |          21 |     NULL | NULL   |      | BTREE      |         |
| geostats |          0 | PRIMARY    |            2 | path        | A         |     1282603 |     NULL | NULL   |      | BTREE      |         |
| geostats |          1 | totalcount |            1 | totalcount  | A         |          21 |     NULL | NULL   |      | BTREE      |         |
| geostats |          1 | daycount   |            1 | daycount    | A         |          21 |     NULL | NULL   |      | BTREE      |         |
| geostats |          1 | timestamp  |            1 | timestamp   | A         |     1282603 |     NULL | NULL   |      | BTREE      |         |
| geostats |          1 | nid        |            1 | nid         | A         |       80162 |     NULL | NULL   | YES  | BTREE      |         |
+----------+------------+------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+

$ cat /etc/my.cnf
[mysqld]
set-variable=max_connections=1500
key_buffer = 8M
max_allowed_packet = 1M
read_buffer_size = 2M
read_rnd_buffer_size = 8M
myisam_sort_buffer_size = 8M

innodb_buffer_pool_size = 256M
innodb_log_file_size = 64M

#innodb_force_recovery=1

How to repeat:
Do not know how to reproduce. There are up to 70 concurrent database connections.

I have last time seen this error reported about 3 years ago.

It started to happen only recently with the increase of the website traffic (and consequently with the number of inserts/updates into the "geostats" table) and/or with the number of records in the table.

mysql> select count(*) from geostats;
+----------+
| count(*) |
+----------+
|  1548595 |
+----------+

Also, when it started to happen the server was running MySQL version 5.0.27. I then upgraded it to .51a in an attempt to fix this problem. But it did not help at all.

Michael,

my colleague set your comments to private, so don't worry.

Michael,

can you post the entire .err log?

This kind of corruption may be a result of incomplete crash recovery after a mysqld crash. If some secondary index records are not 'redone' in the recovery, secondary indexes get out-of-sync from the clustered index.

Regards,

Heikki

We have similar (or same) problem on Debian 5.0.51a MySQL, it start just after upgrade from 5.0.32 on heavy used table (bayes data for spamassassin). Database is restarted with every error. I can provide more info if needed, just tell me exactly what you need.

mysqld[20823]: InnoDB: error in sec index entry update in
mysqld[20823]: InnoDB: index `bayes_token_idx2` of table `bayes/bayes_token`
mysqld[20823]: InnoDB: tuple DATA TUPLE: 3 fields;
mysqld[20823]:  0: len 4; hex 80000001; asc     ;; 1: len 4; hex c8e4768f; asc   v ;; 2: len 5; hex 0265132020; asc  e   ;;
mysqld[20823]: 
mysqld[20823]: InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32
mysqld[20823]:  0: len 4; hex 80000001; asc     ;; 1: len 4; hex c8e4768f; asc   v ;; 2: len 5; hex c4970d000b; asc      ;;
mysqld[20823]: 
mysqld[20823]: TRANSACTION 0 380959710, ACTIVE 0 sec, process no 20822, OS thread id 1153395040 updating or deleting, thread declared inside InnoDB 498
mysqld[20823]: mysql tables in use 1, locked 1
mysqld[20823]: 29 lock struct(s), heap size 6752, undo log entries 59
mysqld[20823]: MySQL thread id 362210, query id 22631043 someserver 192.168.15.15 sa_user update
mysqld[20823]: INSERT INTO bayes_token
mysqld[20823]:                (id, token, spam_count, ham_count, atime)
mysqld[20823]:                VALUES ('1','E<E8><A4>^W\r','1','0','1222932198')
mysqld[20823]:                ON DUPLICATE KEY UPDATE spam_count = GREATEST(spam_count + '1', 0),
mysqld[20823]:                                        ham_count = GREATEST(ham_count + '0', 0
mysqld[20823]: 
mysqld[20823]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com

If you see this error and you have an index on a partial column, first ALTER TABLE <tablename> ENGINE=INNODB to rebuild the whole table and all indexes. See bug #21838. Once you've done that, CHECK TABLE <tablename> to see if it's OK after the rebuild.

If commenting on this bug, please confirm that you have done the rebuild or created the table with version 5.0.48 or later so we can be sure that you're not seeing the fixed bug. We'll also need to see the indexes you're using so we can look for the chance of another problem in that area.

James Day. MySQL Senior Support Engineer, Sun Microsystems

most likely explained by :

Bug 13807811 - BTR_PCUR_RESTORE_POSITION() CAN SKIP A RECORD.

Correction: my last comment should have mentioned bug 28138, which was fixed in 5.0.48 and 5.1.21. Existing damage would remain in the index so you should upgrade to at least that version then drop and add back the secondary index, only applies if you are using a column prefix index.

There is no testcase and not enough details to confirm any bug.
Please open a new bug report if you see corruption on 5.5.54/5.6.27 or newer.