Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-22924

Warning InnoDB: Index 'Marvão_idx3' contains 36 entries, should be 37.

Details

    Description

      Index corruption found during RQG testing
      		 
      Some CHECK TABLE t2 EXTENDED harvested
      		 
      test.t2 check Warning InnoDB: Index 'Marvão_idx3' contains 36 entries, should be 37.
      		 
      And the server error log contains a
      		 
      [rr 76197 241886]2020-06-16 18:31:54 33 [ERROR] InnoDB: Index `Marvão_idx3` of table `test`.`t2` is corrupted
      		 
      [rr 76197 241890]2020-06-16 18:31:54 33 [Note] InnoDB: Load corrupted index `Marvão_idx3` of table `test`.`t2`
      		 
       
      		 
      Work flow:
      		 
      1. Start the server and generate some initial data
      		 
      2. Several concurrent sessions runs a DDL/DML mix
      		 
           and sometimes CHECK TABLE EXTENDED
      		 
      Please note critical events like killing the server process followed by Restart
      		 
      with CrashRecovery are not involved..
      		 
       
      		 
      I have some "rr" trace for the tree
      		 
      origin/bb-10.5-marko 8cad9bc9805ff058e8493d92d4915ca437d16b08
      		 
      which is based on actual 10.5 but contains some non final changes of Marko.
      		 
      Per Marko the failure cannot be caused by his changes.
      		 
       
      		 
      My test machinery has seen the same problem also on
      		 
      10.3.24 origin/10.3 294ac1fbab306e97dad3588a00e3527f2056e7e4 2020-05-19T15:27:22+00:00
      		 
      but the corresponding details are lost.
      		 
      And so its unknown if that was during concurrent load or after crash with recovery.
      		 
       
      		 
      RQG
      		 
      git clone https://github.com/mleich1/rqg --branch experimental RQG
      		 
      origin/experimental 611a31e38a3bc157392c0748c95991b6a248bb3b 2020-06-09T15:31:46+02:00
      		 
       
      		 
      perl rqg.pl \
      		 
      --grammar=conf/mariadb/table_stress_innodb_nocopy.yy \
      		 
      --gendata=conf/mariadb/table_stress.zz \
      		 
      --gendata_sql=conf/mariadb/table_stress.sql \
      		 
      --mysqld=--innodb_use_native_aio=1 \
      		 
      --mysqld=--innodb_lock_schedule_algorithm=fcfs \
      		 
      --mysqld=--loose-idle_write_transaction_timeout=0 \
      		 
      --mysqld=--loose-idle_transaction_timeout=0 \
      		 
      --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      		 
      --mysqld=--connect_timeout=60 \
      		 
      --mysqld=--interactive_timeout=28800 \
      		 
      --mysqld=--slave_net_timeout=60 \
      		 
      --mysqld=--net_read_timeout=30 \
      		 
      --mysqld=--net_write_timeout=60 \
      		 
      --mysqld=--loose-table_lock_wait_timeout=50 \
      		 
      --mysqld=--wait_timeout=28800 \
      		 
      --mysqld=--lock-wait-timeout=86400 \
      		 
      --mysqld=--innodb-lock-wait-timeout=50 \
      		 
      --no-mask \
      		 
      --queries=10000000 \
      		 
      --seed=random \
      		 
      --reporters=Backtrace \
      		 
      --reporters=ErrorLog \
      		 
      --reporters=Deadlock1 \
      		 
      --validators=None \
      		 
      --mysqld=--log_output=none \
      		 
      --mysqld=--log-bin \
      		 
      --mysqld=--log_bin_trust_function_creators=1 \
      		 
      --mysqld=--loose-max-statement-time=30 \
      		 
      --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      		 
      --engine=InnoDB \
      		 
      --restart_timeout=120 \
      		 
      --duration=300 \
      		 
      --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
      		 
      --mysqld=--innodb_stats_persistent=off \
      		 
      --threads=33 \
      		 
      --mysqld=--innodb_page_size=4K \
      		 
      --mysqld=--innodb-buffer-pool-size=256M \
      		 
      --duration=300 \
      		 
      --no_mask \
      		 
      ... certain local settings ...
      		 
       
      		 
      If looking into the attached RQG protocol 002082.log and the RQG call mentioned there please be aware that the "--reporters=CrashRecovery1" just tells
      		 
      that running a work flow invoking kill+restart was planned.
      		 
      But the data corruption was hit before the RQG reporter "CrashRecovery1"
      		 
      would kill the server process.

      Attachments

        Issue Links

          blocks

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14643 InnoDB: Failing assertion: !cursor->index->is_committed()

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23192 Crash in row_search_mvcc() probably related to secondary index corruption

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23563 InnoDB: Failing assertion: !cursor->index->is_committed() in row0ins.cc

          • Major - Major loss of function.
          • Closed
          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-20301 InnoDB's MVCC has O(N^2) behaviors

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23632 ALTER TABLE...ADD KEY creates corrupted index on virtual column

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15532 XA: Assertion `!log->same_pk' failed in row_log_table_apply_delete

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22076 InnoDB: Failing assertion: !cursor->index->is_committed() or Assertion `0' in row_purge_remove_sec_if_poss_leaf after DML/DDL with XA

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22373 Unable to find a record to delete-mark ends up crashing mysqld process after upgrading from 10.1.43 to 10.4

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 15 older comments
            marko Marko Mäkelä added a comment -

            All records in the clustered index page carry DB_TRX_ID=2009=0x7d9. Also the PAGE_MAX_TRX_ID in the secondary index is at that value. The next available transaction identifier (trx_sys.m_max_trx_id) is 2012. The read view of the CHECK TABLE excludes transaction 2009.

            Transaction 2009 modified all 6 rows of the table by executing the statement

            UPDATE table100_innodb_int_autoinc SET col_longtext_ucs2_key = REPEAT( 0xA, 0 ) WHERE col_char_255_utf8_key BETWEEN REPEAT( 0xF5B, 224 ) AND REPEAT( 0xB2, 140 );

            The transaction was started at the event time (when) 4387662 and committed at 4257184. At the time the transaction started, the clustered index leaf pages were 13,14,10,11.

            The CHECK TABLE had started executing on the primary key at when 4255465. At the time the UPDATE transaction is committing, it was executing inside btr_validate_index(), trying to access our secondary index page 5.

            It looks like we must ignore the 6 first records in the secondary index page (which must be excluded from the read view) and concentrate on the delete-marked ones, to see which record is missing and why. Here are all 15 secondary index records that were present when CHECK TABLE counted the records:

            KEY(col_longtext_ucs2_key)

            		 
            (col_longtext_ucs2_key,pk)=
            		 
            page 5:
            		 
            ('',1),('',2),('',3),('',4),('',5),('',6),
            		 
            delete-marked(repeat(0x744,242),1),
            		 
            delete-marked(repeat(0x744,242),2),
            		 
            delete-marked(repeat(0x744,242),3),
            		 
            delete-marked(repeat(0x744,242),4),
            		 
            delete-marked(repeat(0x744,242),5),
            		 
            delete-marked(repeat(0x744,242),6),
            		 
            delete-marked(repeat(0xf76,85),1),
            		 
            delete-marked(repeat(0xf76,85),3),
            		 
            delete-marked(repeat(0xf76,85),6),

            I noticed that also purge is running concurrently with the CHECK TABLE. That should explain why there exist only 3 keys with the value 0xf76.

            I hope to complete the analysis of this trace next week. It is rather challenging due to the amount of concurrency, including page splits and merges in the clustered index.

            marko Marko Mäkelä added a comment - All records in the clustered index page carry DB_TRX_ID=2009=0x7d9. Also the PAGE_MAX_TRX_ID in the secondary index is at that value. The next available transaction identifier ( trx_sys.m_max_trx_id ) is 2012. The read view of the CHECK TABLE excludes transaction 2009. Transaction 2009 modified all 6 rows of the table by executing the statement UPDATE table100_innodb_int_autoinc SET col_longtext_ucs2_key = REPEAT( 0xA, 0 ) WHERE col_char_255_utf8_key BETWEEN REPEAT( 0xF5B, 224 ) AND REPEAT( 0xB2, 140 ); The transaction was started at the event time ( when ) 4387662 and committed at 4257184. At the time the transaction started, the clustered index leaf pages were 13,14,10,11. The CHECK TABLE had started executing on the primary key at when 4255465. At the time the UPDATE transaction is committing, it was executing inside btr_validate_index() , trying to access our secondary index page 5. It looks like we must ignore the 6 first records in the secondary index page (which must be excluded from the read view) and concentrate on the delete-marked ones, to see which record is missing and why. Here are all 15 secondary index records that were present when CHECK TABLE counted the records: KEY(col_longtext_ucs2_key) (col_longtext_ucs2_key,pk)= page 5: ('',1),('',2),('',3),('',4),('',5),('',6), delete-marked(repeat(0x744,242),1), delete-marked(repeat(0x744,242),2), delete-marked(repeat(0x744,242),3), delete-marked(repeat(0x744,242),4), delete-marked(repeat(0x744,242),5), delete-marked(repeat(0x744,242),6), delete-marked(repeat(0xf76,85),1), delete-marked(repeat(0xf76,85),3), delete-marked(repeat(0xf76,85),6), I noticed that also purge is running concurrently with the CHECK TABLE . That should explain why there exist only 3 keys with the value 0xf76. I hope to complete the analysis of this trace next week. It is rather challenging due to the amount of concurrency, including page splits and merges in the clustered index.
            marko Marko Mäkelä added a comment -

            Transaction 2009 updated the clustered index records to col_longtest_ucs2_key='' at the following event times, with the following preceding contents of the record:

            when pk DB_TRX_ID col_longtest_ucs2_key
            4243126 6 0x7d5 repeat(0xf76,85)
            4246790 3 0x7d5 repeat(0xf76,85)
            4247019 1 0x7d5 repeat(0xf76,85)
            4251855 4 0x7d2 repeat(0x744,242)
            4253252 2 0x7d2 repeat(0x744,242)
            4253481 5 0x7d2 repeat(0x744,242)

            This suggests that none of the records that were visible in the secondary index page when CHECK TABLE was executed could actually be purged.

            The UPDATE transaction was holding an S-latch on the secondary index page (5) from event time 4254001 to 4256397.
            At event time 4254061, a purge thread starts waiting for an X-latch on the secondary index page.
            At event time 4255465, the failing CHECK TABLE starts accessing the clustered index.
            Between event time 4256397 and 4256882 the purge thread was holding the X-latch on the secondary index page.
            Between event time 4256918 and 4257017, the same purge thread holds the secondary index X-latch again.
            Between event time 4257031 and 4257048, the UPDATE transaction 2009 holds the X-latch on the secondary index page, so that it can perform the first half of the last update, to delete-mark the record (repeat(0x744,242),5).
            Between event time 4257072 and 4257117, the UPDATE transaction 2009 holds the X-latch on the secondary index page, so that it can perform the second half of the last update, to insert the record ('',5).
            At event time 4257186, the UPDATE transaction 2009 commits.
            Between event time 4257264 and 4257322, the failing CHECK TABLE holds an SX-latch on the secondary index page.
            At event time 4257336, the failing CHECK TABLE acquires an S-latch on the secondary index page. This is the first time it starts counting records in the secondary index.
            At event time 4257868, a purge thread requests an exclusive latch on the secondary index page, while our CHECK TABLE is holding an S-latch.
            At event time 4258247, the failing CHECK TABLE releases the S-latch on the secondary index page.
            At event time 4258372, purge releases the exclusive page latch.
            Between event time 4258406 and 4258406, the same purge thread holds an exclusive page latch.
            Between event time 4259276 and 4259435, the same purge thread holds an exclusive page latch.
            Between event time 4259469 and 4259542, the same purge thread holds an exclusive page latch.
            Between event time 4259576 and 4259649, the same purge thread holds an exclusive page latch.
            Between event time 4259683 and 4260375, the same purge thread holds an exclusive page latch.
            Between event time 4260409 and 4260489, the same purge thread holds an exclusive page latch.
            Between event time 4260523 and 4260596, the same purge thread holds an exclusive page latch.
            Between event time 4260630 and 4260677, the same purge thread holds an exclusive page latch.
            Between event time 4260711 and 4260758, the same purge thread holds an exclusive page latch.
            Between event time 4260792 and 4260847, the same purge thread holds an exclusive page latch.
            Between event time 4260881 and 4260928, the same purge thread holds an exclusive page latch.
            Between event time 4260962 and 4261009, the same purge thread holds an exclusive page latch.
            At event time 4261016, our failing CHECK TABLE acquires an S-latch on the secondary index page.
            At event time 4261047, an UPDATE transaction 2014 starts to wait for an exclusive page latch.
            At event time 4261383, our failing CHECK TABLE releases the S-latch.
            At event time 4261431, the UPDATE transaction 2014 releases the exclusive page latch.
            At event time 4261445, our failing CHECK TABLE acquires an S-latch on the secondary index page.
            At event time 4261457, our failing CHECK TABLE acquires an S-latch on the secondary index page.
            Between event time 4261451 and 4261472, the UPDATE transaction 2014 holds the exclusive page latch.
            Between event time 4261586 and 4261635, a different purge thread holds an exclusive page latch.
            …
            At event time 4263975, we report the count mismatch.

            Because there is so much concurrent activity, it seems infeasible to track down all changes to the page between the commit of the transaction 2009 and the CHECK TABLE. Next, I will determine which ‘raw’ records the CHECK TABLE is observing in the secondary index, and which of them are being miscounted.

            marko Marko Mäkelä added a comment - Transaction 2009 updated the clustered index records to col_longtest_ucs2_key='' at the following event times, with the following preceding contents of the record: when pk DB_TRX_ID col_longtest_ucs2_key 4243126 6 0x7d5 repeat(0xf76,85) 4246790 3 0x7d5 repeat(0xf76,85) 4247019 1 0x7d5 repeat(0xf76,85) 4251855 4 0x7d2 repeat(0x744,242) 4253252 2 0x7d2 repeat(0x744,242) 4253481 5 0x7d2 repeat(0x744,242) This suggests that none of the records that were visible in the secondary index page when CHECK TABLE was executed could actually be purged. The UPDATE transaction was holding an S-latch on the secondary index page (5) from event time 4254001 to 4256397. At event time 4254061, a purge thread starts waiting for an X-latch on the secondary index page. At event time 4255465, the failing CHECK TABLE starts accessing the clustered index. Between event time 4256397 and 4256882 the purge thread was holding the X-latch on the secondary index page. Between event time 4256918 and 4257017, the same purge thread holds the secondary index X-latch again. Between event time 4257031 and 4257048, the UPDATE transaction 2009 holds the X-latch on the secondary index page, so that it can perform the first half of the last update, to delete-mark the record (repeat(0x744,242),5). Between event time 4257072 and 4257117, the UPDATE transaction 2009 holds the X-latch on the secondary index page, so that it can perform the second half of the last update, to insert the record ('',5). At event time 4257186, the UPDATE transaction 2009 commits. Between event time 4257264 and 4257322, the failing CHECK TABLE holds an SX-latch on the secondary index page. At event time 4257336, the failing CHECK TABLE acquires an S-latch on the secondary index page. This is the first time it starts counting records in the secondary index. At event time 4257868, a purge thread requests an exclusive latch on the secondary index page, while our CHECK TABLE is holding an S-latch. At event time 4258247, the failing CHECK TABLE releases the S-latch on the secondary index page. At event time 4258372, purge releases the exclusive page latch. Between event time 4258406 and 4258406, the same purge thread holds an exclusive page latch. Between event time 4259276 and 4259435, the same purge thread holds an exclusive page latch. Between event time 4259469 and 4259542, the same purge thread holds an exclusive page latch. Between event time 4259576 and 4259649, the same purge thread holds an exclusive page latch. Between event time 4259683 and 4260375, the same purge thread holds an exclusive page latch. Between event time 4260409 and 4260489, the same purge thread holds an exclusive page latch. Between event time 4260523 and 4260596, the same purge thread holds an exclusive page latch. Between event time 4260630 and 4260677, the same purge thread holds an exclusive page latch. Between event time 4260711 and 4260758, the same purge thread holds an exclusive page latch. Between event time 4260792 and 4260847, the same purge thread holds an exclusive page latch. Between event time 4260881 and 4260928, the same purge thread holds an exclusive page latch. Between event time 4260962 and 4261009, the same purge thread holds an exclusive page latch. At event time 4261016, our failing CHECK TABLE acquires an S-latch on the secondary index page. At event time 4261047, an UPDATE transaction 2014 starts to wait for an exclusive page latch. At event time 4261383, our failing CHECK TABLE releases the S-latch. At event time 4261431, the UPDATE transaction 2014 releases the exclusive page latch. At event time 4261445, our failing CHECK TABLE acquires an S-latch on the secondary index page. At event time 4261457, our failing CHECK TABLE acquires an S-latch on the secondary index page. Between event time 4261451 and 4261472, the UPDATE transaction 2014 holds the exclusive page latch. Between event time 4261586 and 4261635, a different purge thread holds an exclusive page latch. … At event time 4263975, we report the count mismatch. Because there is so much concurrent activity, it seems infeasible to track down all changes to the page between the commit of the transaction 2009 and the CHECK TABLE . Next, I will determine which ‘raw’ records the CHECK TABLE is observing in the secondary index, and which of them are being miscounted.
            marko Marko Mäkelä added a comment -

            The following record is unexpectedly determined as not visible:

            Thread 4 hit Breakpoint 15, row_search_mvcc (buf=buf@entry=0x621003b4d518 '\276' <repeats 200 times>..., mode=<optimized out>, mode@entry=PAGE_CUR_G, prebuilt=prebuilt@entry=0x62100013b1a0, 
                match_mode=match_mode@entry=0, direction=direction@entry=0) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:5253
            		 
            5253					ut_ad(prebuilt->select_lock_type == LOCK_NONE
            		 
            9: /x *prebuilt.pcur.btr_cur.page_cur.rec@4 = {0x7, 0x44, 0x7, 0x44}
            		 
            11: /x prebuilt.pcur.btr_cur.page_cur.rec[480]@8 = {0x7, 0x44, 0x7, 0x44, 0x80, 0x0, 0x0, 0x2}
            		 
            (rr) when
            		 
            Current event: 4262501

            The clustered index page 12 was looked up at event time 4262479, and it does contain the key (pk=2). It seems that incorrect caching at Row_sel_get_clust_rec_for_mysql::operator() might be to blame for the mismatch.

            At event time 4261371, Row_sel_get_clust_rec_for_mysql::cached_clust_rec had been updated:

            Thread 4 hit Hardware watchpoint 17: -location cached_clust_rec
            		 
             
            		 
            Old value = (const rec_t *) 0x5acc21d84083 <incomplete sequence \354\200>
            		 
            New value = (const rec_t *) 0x5acc21a18083 "\200"
            		 
            Row_sel_get_clust_rec_for_mysql::operator() (this=this@entry=0x27ed5a27a540, prebuilt=prebuilt@entry=0x62100013b1a0, sec_index=sec_index@entry=0x61700006b7a0, rec=<optimized out>, thr=thr@entry=0x62100013b980, 
                out_rec=out_rec@entry=0x27ed5a27a040, offsets=<optimized out>, offset_heap=<optimized out>, vrow=<optimized out>, mtr=<optimized out>) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:3418
            		 
            3418					cached_old_vers = old_vers;
            		 
            (rr) when
            		 
            Current event: 4261371
            		 
            (rr) p/x *clust_rec@20
            		 
            $88 = {0x80, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd9, 0x4c, 0x0, 0x0, 0x6, 0x31, 0x8, 0xc6, 0x6d, 0x6f, 0x64}

            Note: (pk,DB_TRX_ID)=(1,2009), not (2,2009).
            A little later, we get to check whether the secondary index record with pk=2 should exist in our read view:

            (rr) 
            Row_sel_get_clust_rec_for_mysql::operator() (this=this@entry=0x27ed5a27a540, prebuilt=prebuilt@entry=0x62100013b1a0, sec_index=sec_index@entry=0x61700006b7a0, rec=<optimized out>, thr=thr@entry=0x62100013b980, 
                out_rec=out_rec@entry=0x27ed5a27a040, offsets=<optimized out>, offset_heap=<optimized out>, vrow=<optimized out>, mtr=<optimized out>) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:3258
            		 
            3258		clust_rec = btr_pcur_get_rec(prebuilt->clust_pcur);
            		 
            (rr) 
            3260		prebuilt->clust_pcur->trx_if_known = trx;
            		 
            (rr) p clust_rec
            		 
            $91 = (const rec_t *) 0x5acc21a18083 "\200"
            		 
            (rr) when
            		 
            Current event: 4262489
            		 
            (rr) p/x *clust_rec@20
            		 
            $92 = {0x80, 0x0, 0x0, 0x2, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd9, 0x4c, 0x0, 0x0, 0x6, 0x32, 0x6, 0xce, 0x73, 0x75, 0x70}

            Note: clust_rec is at the same pointer value, but it now points to a different record, (pk,DB_TRX_ID)=(2,2009), presumably because there has been a lot of purge and UPDATE activity that caused the records to move around.
            A little later, we hit the bug:

            3405				if (clust_rec != cached_clust_rec) {
            		 
            (rr) 
            3420					err = DB_SUCCESS;
            		 
            (rr) 
            3421					old_vers = cached_old_vers;
            		 
            (rr) p/x *cached_old_vers@20
            		 
            $93 = {0x80, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd5, 0x49, 0x0, 0x0, 0x6, 0x30, 0x0, 0x38, 0x6d, 0x6f, 0x64}
            		 
            (rr) when
            		 
            Current event: 4262489

            So, we wrongly determine the old version of the record pk=2 to be something with pk=1, and subsequently determine that the secondary index record does not exist in the read view.

            This incorrect logic, which was introduced in MDEV-20301, would likely have been caught much earlier if we had had a debug assertion to check that the PRIMARY KEY values are equal.

            The bug seems to affect MVCC reads of secondary index records only. The MDEV-20301 ‘optimization’ was not applied to checks for implicit locks.

            marko Marko Mäkelä added a comment - The following record is unexpectedly determined as not visible: Thread 4 hit Breakpoint 15, row_search_mvcc (buf=buf@entry=0x621003b4d518 '\276' <repeats 200 times>..., mode=<optimized out>, mode@entry=PAGE_CUR_G, prebuilt=prebuilt@entry=0x62100013b1a0, match_mode=match_mode@entry=0, direction=direction@entry=0) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:5253 5253 ut_ad(prebuilt->select_lock_type == LOCK_NONE 9: /x *prebuilt.pcur.btr_cur.page_cur.rec@4 = {0x7, 0x44, 0x7, 0x44} 11: /x prebuilt.pcur.btr_cur.page_cur.rec[480]@8 = {0x7, 0x44, 0x7, 0x44, 0x80, 0x0, 0x0, 0x2} (rr) when Current event: 4262501 The clustered index page 12 was looked up at event time 4262479, and it does contain the key (pk=2). It seems that incorrect caching at Row_sel_get_clust_rec_for_mysql::operator() might be to blame for the mismatch. At event time 4261371, Row_sel_get_clust_rec_for_mysql::cached_clust_rec had been updated: Thread 4 hit Hardware watchpoint 17: -location cached_clust_rec   Old value = (const rec_t *) 0x5acc21d84083 <incomplete sequence \354\200> New value = (const rec_t *) 0x5acc21a18083 "\200" Row_sel_get_clust_rec_for_mysql::operator() (this=this@entry=0x27ed5a27a540, prebuilt=prebuilt@entry=0x62100013b1a0, sec_index=sec_index@entry=0x61700006b7a0, rec=<optimized out>, thr=thr@entry=0x62100013b980, out_rec=out_rec@entry=0x27ed5a27a040, offsets=<optimized out>, offset_heap=<optimized out>, vrow=<optimized out>, mtr=<optimized out>) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:3418 3418 cached_old_vers = old_vers; (rr) when Current event: 4261371 (rr) p/x *clust_rec@20 $88 = {0x80, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd9, 0x4c, 0x0, 0x0, 0x6, 0x31, 0x8, 0xc6, 0x6d, 0x6f, 0x64} Note: (pk,DB_TRX_ID)=(1,2009), not (2,2009). A little later, we get to check whether the secondary index record with pk=2 should exist in our read view: (rr) Row_sel_get_clust_rec_for_mysql::operator() (this=this@entry=0x27ed5a27a540, prebuilt=prebuilt@entry=0x62100013b1a0, sec_index=sec_index@entry=0x61700006b7a0, rec=<optimized out>, thr=thr@entry=0x62100013b980, out_rec=out_rec@entry=0x27ed5a27a040, offsets=<optimized out>, offset_heap=<optimized out>, vrow=<optimized out>, mtr=<optimized out>) at /home/mleich/Server/10.5A/storage/innobase/row/row0sel.cc:3258 3258 clust_rec = btr_pcur_get_rec(prebuilt->clust_pcur); (rr) 3260 prebuilt->clust_pcur->trx_if_known = trx; (rr) p clust_rec $91 = (const rec_t *) 0x5acc21a18083 "\200" (rr) when Current event: 4262489 (rr) p/x *clust_rec@20 $92 = {0x80, 0x0, 0x0, 0x2, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd9, 0x4c, 0x0, 0x0, 0x6, 0x32, 0x6, 0xce, 0x73, 0x75, 0x70} Note: clust_rec is at the same pointer value, but it now points to a different record, (pk,DB_TRX_ID)=(2,2009), presumably because there has been a lot of purge and UPDATE activity that caused the records to move around. A little later, we hit the bug: 3405 if (clust_rec != cached_clust_rec) { (rr) 3420 err = DB_SUCCESS; (rr) 3421 old_vers = cached_old_vers; (rr) p/x *cached_old_vers@20 $93 = {0x80, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x7, 0xd5, 0x49, 0x0, 0x0, 0x6, 0x30, 0x0, 0x38, 0x6d, 0x6f, 0x64} (rr) when Current event: 4262489 So, we wrongly determine the old version of the record pk=2 to be something with pk=1, and subsequently determine that the secondary index record does not exist in the read view. This incorrect logic, which was introduced in MDEV-20301 , would likely have been caught much earlier if we had had a debug assertion to check that the PRIMARY KEY values are equal. The bug seems to affect MVCC reads of secondary index records only. The MDEV-20301 ‘optimization’ was not applied to checks for implicit locks.
            marko Marko Mäkelä added a comment -

            We might try to rescue the MDEV-20301 logic by checking that the FIL_PAGE_LSN of the page is unchanged. (Note that before MDEV-21132 in 10.5.0, the latest value of FIL_PAGE_LSN could be stored in newest_lsn, and hence that field must be checked as well.) We should also add a debug assertion that the (pk,DB_TRX_ID,DB_ROLL_PTR) match between clust_rec and cached_clust_rec, and that the (pk) matches with cached_old_vers.

            marko Marko Mäkelä added a comment - We might try to rescue the MDEV-20301 logic by checking that the FIL_PAGE_LSN of the page is unchanged. (Note that before MDEV-21132 in 10.5.0, the latest value of FIL_PAGE_LSN could be stored in newest_lsn , and hence that field must be checked as well.) We should also add a debug assertion that the (pk,DB_TRX_ID,DB_ROLL_PTR) match between clust_rec and cached_clust_rec , and that the (pk) matches with cached_old_vers .
            marko Marko Mäkelä added a comment -

            This bug is blocking the testing effort for catching other corruption bugs. I will try to address this myself as soon as possible.

            marko Marko Mäkelä added a comment - This bug is blocking the testing effort for catching other corruption bugs. I will try to address this myself as soon as possible.

            People

              marko Marko Mäkelä
              mleich Matthias Leich
              Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.