MySQL Bugs: #70214: Record in index was not found on rollback, trying to insert

Bug #70214	Record in index was not found on rollback, trying to insert
Submitted:	2 Sep 2013 11:10	Modified:	2 Jun 2015 13:57
Reporter:	Džiugas Baltrūnas	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6.13, 5.7.5	OS:	Linux (Ubuntu 12.04.2 LTS)
Assigned to:		CPU Architecture:	Any

Description:
Long-running transaction caused the following error on the secondary index:

2013-09-02 13:07:40 31214 [Warning] InnoDB: record in index idx_stats was not found on rollback, trying to insert
InnoDB: error in sec index entry del undo in
InnoDB: index `idx_stats` of table `nne`.`measurement_generic_data` /* Partition `p20130817` */
InnoDB: tuple DATA TUPLE: 4 fields;
 0: len 4; hex 00000012; asc     ;;
 1: len 8; hex 999062626f0a237f; asc   bbo # ;;
 2: len 4; hex 0000015c; asc    \;;
 3: len 4; hex eeef7040; asc   p@;;

InnoDB: record PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000012; asc     ;;
 1: len 8; hex 999062626f0a0ee0; asc   bbo   ;;
 2: len 4; hex 00000292; asc     ;;
 3: len 4; hex c65d9388; asc  ]  ;;

TRANSACTION 186613007, ACTIVE 42885 sec rollback of SQL statement
mysql tables in use 1, locked 1
ROLLING BACK 138875 lock struct(s), heap size 14514616, 17119648 row lock(s), undo log entries 12518806
MySQL thread id 18923, OS thread handle 0x7fb1971cb700, query id 3985291 localhost root query end
UPDATE measurement_generic_data PARTITION (p20130817) SET stats = 40 WHERE stats between 10 and 19

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

The same error is written to the error.log file continuously.

Table structure:

CREATE TABLE `measurement_generic_data` (
  `ts` datetime(6) NOT NULL,
  `mi_id` int(10) unsigned NOT NULL,
  `seq` int(10) unsigned DEFAULT NULL,
  `xml_data` varchar(1024) NOT NULL,
  `crc` int(10) unsigned NOT NULL DEFAULT '0',
  `stats` int(10) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`ts`,`mi_id`,`crc`),
  KEY `idx_stats` (`stats`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=DYNAMIC
/*!50500 PARTITION BY RANGE  COLUMNS(ts)
(PARTITION p20130628 VALUES LESS THAN ('2013-06-29') ENGINE = InnoDB,
 PARTITION p20130629 VALUES LESS THAN ('2013-06-30') ENGINE = InnoDB,
 PARTITION p20130630 VALUES LESS THAN ('2013-07-01') ENGINE = InnoDB,
 PARTITION p20130701 VALUES LESS THAN ('2013-07-02') ENGINE = InnoDB,
 PARTITION p20130702 VALUES LESS THAN ('2013-07-03') ENGINE = InnoDB,
 PARTITION p20130703 VALUES LESS THAN ('2013-07-04') ENGINE = InnoDB,
 PARTITION p20130704 VALUES LESS THAN ('2013-07-05') ENGINE = InnoDB,
 PARTITION p20130705 VALUES LESS THAN ('2013-07-06') ENGINE = InnoDB,
 PARTITION p20130706 VALUES LESS THAN ('2013-07-07') ENGINE = InnoDB,
 PARTITION p20130707 VALUES LESS THAN ('2013-07-08') ENGINE = InnoDB,
 PARTITION p20130708 VALUES LESS THAN ('2013-07-09') ENGINE = InnoDB,
 PARTITION p20130709 VALUES LESS THAN ('2013-07-10') ENGINE = InnoDB,
 PARTITION p20130710 VALUES LESS THAN ('2013-07-11') ENGINE = InnoDB,
 PARTITION p20130711 VALUES LESS THAN ('2013-07-12') ENGINE = InnoDB,
 PARTITION p20130712 VALUES LESS THAN ('2013-07-13') ENGINE = InnoDB,
 PARTITION p20130713 VALUES LESS THAN ('2013-07-14') ENGINE = InnoDB,
 PARTITION p20130714 VALUES LESS THAN ('2013-07-15') ENGINE = InnoDB,
 PARTITION p20130715 VALUES LESS THAN ('2013-07-16') ENGINE = InnoDB,
 PARTITION p20130716 VALUES LESS THAN ('2013-07-17') ENGINE = InnoDB,
 PARTITION p20130717 VALUES LESS THAN ('2013-07-18') ENGINE = InnoDB,
 PARTITION p20130718 VALUES LESS THAN ('2013-07-19') ENGINE = InnoDB,
 PARTITION p20130719 VALUES LESS THAN ('2013-07-20') ENGINE = InnoDB,
 PARTITION p20130720 VALUES LESS THAN ('2013-07-21') ENGINE = InnoDB,
 PARTITION p20130721 VALUES LESS THAN ('2013-07-22') ENGINE = InnoDB,
 PARTITION p20130722 VALUES LESS THAN ('2013-07-23') ENGINE = InnoDB,
 PARTITION p20130723 VALUES LESS THAN ('2013-07-24') ENGINE = InnoDB,
 PARTITION p20130724 VALUES LESS THAN ('2013-07-25') ENGINE = InnoDB,
 PARTITION p20130725 VALUES LESS THAN ('2013-07-26') ENGINE = InnoDB,
 PARTITION p20130726 VALUES LESS THAN ('2013-07-27') ENGINE = InnoDB,
 PARTITION p20130727 VALUES LESS THAN ('2013-07-28') ENGINE = InnoDB,
 PARTITION p20130728 VALUES LESS THAN ('2013-07-29') ENGINE = InnoDB,
 PARTITION p20130729 VALUES LESS THAN ('2013-07-30') ENGINE = InnoDB,
 PARTITION p20130730 VALUES LESS THAN ('2013-07-31') ENGINE = InnoDB,
 PARTITION p20130731 VALUES LESS THAN ('2013-08-01') ENGINE = InnoDB,
 PARTITION p20130801 VALUES LESS THAN ('2013-08-02') ENGINE = InnoDB,
 PARTITION p20130802 VALUES LESS THAN ('2013-08-03') ENGINE = InnoDB,
 PARTITION p20130803 VALUES LESS THAN ('2013-08-04') ENGINE = InnoDB,
 PARTITION p20130804 VALUES LESS THAN ('2013-08-05') ENGINE = InnoDB,
 PARTITION p20130805 VALUES LESS THAN ('2013-08-06') ENGINE = InnoDB,
 PARTITION p20130806 VALUES LESS THAN ('2013-08-07') ENGINE = InnoDB,
 PARTITION p20130807 VALUES LESS THAN ('2013-08-08') ENGINE = InnoDB,
 PARTITION p20130808 VALUES LESS THAN ('2013-08-09') ENGINE = InnoDB,
 PARTITION p20130809 VALUES LESS THAN ('2013-08-10') ENGINE = InnoDB,
 PARTITION p20130810 VALUES LESS THAN ('2013-08-11') ENGINE = InnoDB,
 PARTITION p20130811 VALUES LESS THAN ('2013-08-12') ENGINE = InnoDB,
 PARTITION p20130812 VALUES LESS THAN ('2013-08-13') ENGINE = InnoDB,
 PARTITION p20130813 VALUES LESS THAN ('2013-08-14') ENGINE = InnoDB,
 PARTITION p20130814 VALUES LESS THAN ('2013-08-15') ENGINE = InnoDB,
 PARTITION p20130815 VALUES LESS THAN ('2013-08-16') ENGINE = InnoDB,
 PARTITION p20130816 VALUES LESS THAN ('2013-08-17') ENGINE = InnoDB,
 PARTITION p20130817 VALUES LESS THAN ('2013-08-18') ENGINE = InnoDB,
 PARTITION p20130818 VALUES LESS THAN ('2013-08-19') ENGINE = InnoDB,
 PARTITION p20130819 VALUES LESS THAN ('2013-08-20') ENGINE = InnoDB,
 PARTITION p20130820 VALUES LESS THAN ('2013-08-21') ENGINE = InnoDB,
 PARTITION p20130821 VALUES LESS THAN ('2013-08-22') ENGINE = InnoDB,
 PARTITION p20130822 VALUES LESS THAN ('2013-08-23') ENGINE = InnoDB,
 PARTITION p20130823 VALUES LESS THAN ('2013-08-24') ENGINE = InnoDB,
 PARTITION p20130824 VALUES LESS THAN ('2013-08-25') ENGINE = InnoDB,
 PARTITION p20130825 VALUES LESS THAN ('2013-08-26') ENGINE = InnoDB,
 PARTITION p20130826 VALUES LESS THAN ('2013-08-27') ENGINE = InnoDB,
 PARTITION p20130827 VALUES LESS THAN ('2013-08-28') ENGINE = InnoDB,
 PARTITION p20130828 VALUES LESS THAN ('2013-08-29') ENGINE = InnoDB,
 PARTITION p20130829 VALUES LESS THAN ('2013-08-30') ENGINE = InnoDB,
 PARTITION p20130830 VALUES LESS THAN ('2013-08-31') ENGINE = InnoDB,
 PARTITION p20130831 VALUES LESS THAN ('2013-09-01') ENGINE = InnoDB,
 PARTITION p20130901 VALUES LESS THAN ('2013-09-02') ENGINE = InnoDB,
 PARTITION p20130902 VALUES LESS THAN ('2013-09-03') ENGINE = InnoDB,
 PARTITION p20130903 VALUES LESS THAN ('2013-09-04') ENGINE = InnoDB,
 PARTITION p20130904 VALUES LESS THAN ('2013-09-05') ENGINE = InnoDB,
 PARTITION p20130905 VALUES LESS THAN ('2013-09-06') ENGINE = InnoDB,
 PARTITION p20130906 VALUES LESS THAN ('2013-09-07') ENGINE = InnoDB);

Transaction:

                    trx_id: 186613007
                 trx_state: ROLLING BACK
               trx_started: 2013-09-02 01:12:55
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 12717018
       trx_mysql_thread_id: 18923
                 trx_query: UPDATE measurement_generic_data PARTITION (p20130817) SET stats = 40 WHERE stats between 10 and 19
       trx_operation_state: rollback of SQL statement
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 138875
     trx_lock_memory_bytes: 14514616
           trx_rows_locked: 17119648
         trx_rows_modified: 12578143
   trx_concurrency_tickets: 0
       trx_isolation_level: READ COMMITTED
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 10000
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
15 rows in set (0.69 sec)

How to repeat:
N/A

It also happened today:

InnoDB: error in sec index entry update in
InnoDB: index `idx_stats` of table `nne`.`measurement_generic_data` /* Partition `p20130901` */
InnoDB: tuple DATA TUPLE: 4 fields;
 0: len 4; hex 0000000d; asc     ;;
 1: len 8; hex 9990821be200660d; asc       f ;;
 2: len 4; hex 00000391; asc     ;;
 3: len 4; hex 25ca57a2; asc % W ;;

InnoDB: record PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 0000000d; asc     ;;
 1: len 8; hex 9990821be101a789; asc         ;;
 2: len 4; hex 000000df; asc     ;;
 3: len 4; hex ab48fc82; asc  H  ;;

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

So the initial error is always "error in sec index entry update in" and "error in sec index entry del undo in" is a follow-up when the transaction is being rolled back.

This seems to be very similar to http://bugs.mysql.com/bug.php?id=37364, which I believe was supposed to be fixed a long time ago.

Thank you for the report.

Please provide output of SHOW VARIABLES LIKE 'innodb%'

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

I see this occasionally on 5.6.19 on a generic multithreaded testcase against a table with many indexes, and partitioned.  The table only gets ~4 rows in total that are updated/deleted/replaced/inserted in many threads.

2014-07-01 20:27:28 7056 [Warning] InnoDB: record in index c_4 was not found on rollback, trying to insert
InnoDB: error in sec index entry del undo in
InnoDB: index `d` of table `test`.`t3` /* Partition `p0` */
InnoDB: tuple DATA TUPLE: 3 fields;
 0: SQL NULL;
 1: len 1; hex 81; asc  ;;
 2: SQL NULL;

InnoDB: record PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 696e66696d756d00; asc infimum ;;

Time to verify this.  

Will upload a .c testcase.  
Basically it consists of this table structure:

create table t1(a tinyint primary key,b tinyint,c tinyint,d tinyint,key(a),key(b),key(c),key(a,b,c),key(a,b),key(b,c),key(c,a),key(a,c),key(c,b),key(c,a,b),key(d,a,b),key(b,a,d),key(d,a))engine=innodb default charset latin1 row_format=dynamic partition by key(a) partitions 3;

And these SQL in multiple threads in random order:

set @a:=floor(cast(rand()*3 as unsigned));
update ignore t1 set a=1,b=1,c=1,d=1 where a > 0 limit 1;
insert into t1(a,b,c,d) values(@a,0,0,0) on duplicate key update a=@a;
delete from t1 where a <> @a limit 1;

testcase, see top of file to build/host/user setup

Attachment: bug70214.c (text/plain), 10.47 KiB.

I should mention the testcase takes about a minute to repeat on a *release* build of mysqld using a very fast disk (ramdisk!) for the datadir.

Another testcase on:
Bug 18631496 - MULTIPLE PURGE THREADS - CORRUPTION - ERROR IN SEC INDEX ENTRY UPDATE

This still affects 5.6.21 release:

Version: '5.6.21-enterprise-commercial-advanced'  socket: ''  port: 3306
InnoDB: tried to purge sec index entry not marked for deletion in
InnoDB: index "d_2" of table "test"."t3" /* Partition "p0" */
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 1; hex 80; asc  ;;
 1: len 1; hex 83; asc  ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 1; hex 80; asc  ;;
 1: len 1; hex 83; asc  ;;

InnoDB: tried to purge sec index entry not marked for deletion in
InnoDB: index "c_4" of table "test"."t3" /* Partition "p2" */
InnoDB: tuple DATA TUPLE: 3 fields;
 0: len 1; hex 81; asc  ;;
 1: len 1; hex 81; asc  ;;
 2: len 1; hex 81; asc  ;;

Still happens on latest mysql-trunk (5.7.6 revno 8947) also:

Version: '5.7.6-m16'  socket: ''  port: 3306  MySQL Community Server
InnoDB: tried to purge sec index entry not marked for deletion in
InnoDB: index "d" of table "test"."t1" /* Partition "p2" */
InnoDB: tuple DATA TUPLE: 3 fields;
 0: len 1; hex 81; asc  ;;
 1: len 1; hex 81; asc  ;;
 2: len 1; hex 81; asc  ;;

Just noting 5.6.23 still affected by my testcase.
Version: '5.6.23'  socket: ''  port: 3306  MySQL Community Server (GPL)
InnoDB: tried to purge sec index entry not marked for deletion in
InnoDB: index "c_3" of table "test"."t3" /* Partition "p2" */
InnoDB: tuple DATA TUPLE: 3 fields;
 0: len 1; hex 80; asc  ;;
 1: len 1; hex 80; asc  ;;
 2: len 1; hex 81; asc  ;;

InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 1; hex 80; asc  ;;
 1: len 1; hex 80; asc  ;;
 2: len 1; hex 81; asc  ;;

InnoDB: tried to purge sec index entry not marked for deletion in
InnoDB: index "c_4" of table "test"."t3" /* Partition "p2" */
InnoDB: tuple DATA TUPLE: 3 fields;
 0: len 1; hex 80; asc  ;;
 1: len 1; hex 81; asc  ;;
 2: len 1; hex 80; asc  ;;

Repeatable on current trunk also:

Version: '5.8.0-m17'  socket: ''  port: 3306  MySQL Community Server (GPL)
[ERROR] InnoDB: tried to purge non-delete-marked record in index `a_3` of table `test`.`t3` /* Partition `p2` */: tuple: TUPLE (info_bits=0, 2 fields): {[1] (0x01),[1] (0x00)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[1] (0x01),[1] (0x00)}

Posted by developer:
 
Side note: I added this error message in MySQL 5.6, as part of the online ALTER TABLE work. During the last phase of ALTER TABLE...ADD INDEX, rollback of DELETE may legitimately have to insert missing records into a freshly built secondary index. When concurrent DDL is not involved, records should never be missing on rollback.

This test case is not using any concurrent DDL. It is possible that this bug exists already in MySQL 5.5, which is not issuing any messages about it.

Posted by developer:
 
When I ran the test case (bug70214.c) given by Shane Bester the following assert failed (in function row_purge_remove_sec_if_poss_leaf()):

445                         /* Only delete-marked records should be purged. */
446                         if (!rec_get_deleted_flag(
447                                 btr_cur_get_rec(btr_cur),
448                                 dict_table_is_comp(index->table))) {
449 
450                                 fputs("InnoDB: tried to purge sec index"
451                                       " entry not marked for deletion in\n"
452                                       "InnoDB: ", stderr);
453                                 dict_index_name_print(stderr, NULL, index);
454                                 fputs("\n"
455                                       "InnoDB: tuple ", stderr);
456                                 dtuple_print(stderr, entry);
457                                 fputs("\n"
458                                       "InnoDB: record ", stderr);
459                                 rec_print(stderr, btr_cur_get_rec(btr_cur),
460                                           index);
461                                 putc('\n', stderr);
462 
463                                 ut_ad(0);
464 
465                                 btr_pcur_close(&pcur);
466 
467                                 goto func_exit_no_pcur;
468                         }

The issue could be specific to a partitioned table.  Will investigate further.

Posted by developer:
 
commit cecc9cb360b92a9dcec1438459bad7a272c171c1
Author: Annamalai Gurusami <annamalai.gurusami@oracle.com>
Date:   Sat May 9 14:02:53 2015 +0530

    Bug #19138298 RECORD IN INDEX WAS NOT FOUND ON ROLLBACK, TRYING TO INSERT
    
    Scenario:
    
    1. The purge thread takes an undo log record and parses it and forms
       the record to be purged. We have the primary and secondary keys
       to locate the actual records.
    2. Using the secondary index key, we search in the secondary index.
       One record is found.
    3. Then it is checked if this record can be purged.  The answer is we
       can purge this record.  To determine this we look up the clustered
       index record.  Either there is no corresponding clustered index
       record, or the matching clustered index record is delete marked.
    4. Then we check whether the secondary index record is delete marked.
       We find that it is not delete marked.  We report warning in optimized
       build and assert in debug build.
    
    Problem:
    
    In step 3, we report that the record is purgeable even though it is
    not delete marked.  This is because of inconsistency between the
    following members of purge_node_t structure - found_clust, ref and pcur.
    
    Solution:
    
    In the row_purge_reposition_pcur(), if the persistent cursor restore
    fails, then reset the purge_node_t->found_clust member.  This will
    keep the members of purge_node_t structure in a consistent state.

Posted by developer:
 
Fixed as of the upcoming 5.5.45, 5.6.26, 5.7.8, 5.8.0 releases, and here's the changelog entry:

An index record was not found on rollback due to inconsistencies in the
"purge_node_t" structure. 

Thank you for the bug report.

Revised changelog entry as follows:

An index record was not found on rollback due to inconsistencies in the
purge_node_t structure. The inconsistency resulted in warnings and error
messages such as error in sec index entry update, unable to purge a
record, and tried to purge sec index entry not marked for deletion.