Bug #99286 Concurrent update cause crash in row_search_mvcc
Submitted: 17 Apr 2020 7:11 Modified: 20 Oct 2020 6:00
Reporter: zkong kong Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.29 OS:CentOS
Assigned to: CPU Architecture:Any

[17 Apr 2020 7:11] zkong kong
Description:
In our production environment:
The server crashed several times these days:
InnoDB: Assertion failure in thread 47758491551488 in file rem0rec.cc line 586
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
06:05:59 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=4
max_threads=151
thread_count=4
connection_count=4
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61035 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2b6fe0000b70
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 2b6fa3ec7d00 thread_stack 0x40000
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(my_print_stacktrace+0x35)[0x18460a6]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(handle_fatal_signal+0x3f6)[0xe88063]
/lib64/libpthread.so.0(+0xf6d0)[0x2b6f998966d0]
/lib64/libc.so.6(gsignal+0x37)[0x2b6f9b211277]
/lib64/libc.so.6(abort+0x148)[0x2b6f9b212968]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld[0x1ac9962]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z20rec_get_offsets_funcPKhPK12dict_index_tPmmPKcmPP16mem_block_info_t+0x121)[0x19a36a3]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z15row_search_mvccPh15page_cur_mode_tP14row_prebuilt_tmm+0x16f3)[0x1a281ff]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN11ha_innobase10index_readEPhPKhj16ha_rkey_function+0x43e)[0x18985b4]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN7handler14index_read_mapEPhPKhm16ha_rkey_function+0x64)[0xf137c8]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x1b0)[0xf053e4]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN7handler16read_range_firstEPK12st_key_rangeS2_bb+0xed)[0xf0ef3b]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN7handler21multi_range_read_nextEPPc+0x14f)[0xf0ce7d]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN10DsMrr_impl10dsmrr_nextEPPc+0x3a)[0xf0dd38]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN11ha_innobase21multi_range_read_nextEPPc+0x2a)[0x18aa52e]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN18QUICK_RANGE_SELECT8get_nextEv+0xa8)[0x16f1b88]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld[0x1431816]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z12mysql_updateP3THDR4ListI4ItemES4_y15enum_duplicatesPyS6_+0x17f4)[0x15c04cd]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN14Sql_cmd_update23try_single_table_updateEP3THDPb+0x25b)[0x15c6de7]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_ZN14Sql_cmd_update7executeEP3THD+0x93)[0x15c7353]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z21mysql_execute_commandP3THDb+0x2b5d)[0x150e6a0]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x639)[0x1513ddd]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xc9a)[0x15096a5]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(_Z10do_commandP3THD+0x4b2)[0x150851d]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(handle_connection+0x1e0)[0x1639004]
/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/bu-Debug/sql/mysqld(pfs_spawn_thread+0x170)[0x1cc171c]
/lib64/libpthread.so.0(+0x7e25)[0x2b6f9988ee25]
/lib64/libc.so.6(clone+0x6d)[0x2b6f9b2d9bad]

How to repeat:
We found that the prev_rec may be invalid when concurrent update a record. The later one can't lock the record and retry after a mtr_commit. When the page changed by purge thread and this is the last record of a page it may crash.

We produce the crash by adding some sync points:

mysql-server kongzhi$ git diff
diff --git a/storage/innobase/row/row0sel.cc b/storage/innobase/row/row0sel.cc
index c37e7908bc5..06880e1bcca 100644
--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -5526,10 +5526,12 @@ no_gap_lock:
                        lock_type = LOCK_REC_NOT_GAP;
                }

+        DBUG_EXECUTE_IF("read_mvcc_before_lock_rec", sleep(1););
                err = sel_set_rec_lock(pcur,
                                       rec, index, offsets,
                                       prebuilt->select_lock_type,
                                       lock_type, thr, &mtr);
+        DBUG_EXECUTE_IF("read_mvcc_after_lock_rec", sleep(2););

                switch (err) {
                        const rec_t*    old_vers;
@@ -6152,6 +6154,7 @@ lock_wait_or_error:

 lock_table_wait:
        mtr_commit(&mtr);
+    DBUG_EXECUTE_IF("sleep_after_mtr_commit", sleep(10););
        mtr_has_extra_clust_latch = FALSE;

        trx->error_state = err;

And use the mtr:

--source include/have_debug_sync.inc
SET @saved_global_isolation= @@global.transaction_isolation;
SET @@global.transaction_isolation= 'READ-COMMITTED';

--connect(con1,localhost,root,'',)
--connect(con2,localhost,root,'',)
--connect(con3,localhost,root,'',)

connection con1;

#construct a big second index row
create table t(id int primary key, k varchar(1024), status int, key k1(k)) charset=latin1;

#prepare data
--disable_query_log
let $i=10000;
#let $i=5000;
while ($i) {
  eval insert into t values($i, repeat('$i', 150), $i);
  dec $i;
}

--enable_query_log
delete from t where k='100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000';
delete from t where k='101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010101010';
delete from t where k='100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009100910091009';
delete from t where k='100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008100810081008';
delete from t where k='100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007100710071007';
delete from t where k>='101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012101210121012';

sleep 2;

connection con2;
set session debug="+d,read_mvcc_after_lock_rec";
send update t set k='101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111010' where k='101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011';
connection con1;
set session debug="+d, compare_end_range";
set session debug="+d, read_mvcc_before_lock_rec";
set session debug="+d, sleep_after_mtr_commit";
send update t set k='101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111000' where k='101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011101110111011';
connection con3;
sleep 7;
insert into t values(10001, '1000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100001000010000100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000', 10001);

connection con1;
--reap
set session debug="-d, compare_end_range";
set session debug="-d, sleep_after_mtr_commit";
SET @@global.transaction_isolation= @saved_global_isolation;
drop table t;

The rec is corrupt and gdb at the crash point:
rec_get_offsets_func (
    rec=0x2aaab91c7bba "10581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058105810581058"..., index=0x2aaaf001b320, offsets=0x2aaab3fdf730, n_fields=18446744073709551615,
    file=0x21eda28 "/u01/kongzhi.kz/mysql-servers/mysql-5.7.29/storage/innobase/row/row0sel.cc", line=5231, heap=0x2aaab3fdffa0)

Suggested fix:
It's affected by this commit:
https://github.com/mysql/mysql-server/commit/2f6741ef8e729e8ea6723ca434f95a40036e1d25

Avoid the crash by setting the prev_rec to NULL before mtr_commit.

diff --git a/storage/innobase/row/row0sel.cc b/storage/innobase/row/row0sel.cc
index c37e7908bc5..617c93fba39 100644
--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -6091,7 +6091,7 @@ next_rec:
                if (!spatial_search) {
                        btr_pcur_store_position(pcur, &mtr);
                }
-
+                prev_rec = NULL;
                mtr_commit(&mtr);
                mtr_has_extra_clust_latch = FALSE;

@@ -6151,6 +6151,7 @@ lock_wait_or_error:
        }

 lock_table_wait:
+        prev_rec = NULL;
        mtr_commit(&mtr);
        mtr_has_extra_clust_latch = FALSE;
[18 Apr 2020 2:02] zkong kong
change Category to InnoDB
[20 Apr 2020 6:16] MySQL Verification Team
Hello zkong kong,

Thank you for the report and feedback.
I tried to reproduce reported problem using provided steps but not seeing any issues. May I request you to please provide complete cmake options, gcc version used for the build along with OS details to reproduce issue at our end? Thank you.

-
export LD_LIBRARY_PATH=/export/umesh/utils/GCC-7.3.0/lib64
export CC=/export/umesh/utils/GCC-7.3.0/bin/gcc
export CPP=/export/umesh/utils/GCC-7.3.0/bin/cpp
export CXX=/export/umesh/utils/GCC-7.3.0/bin/c++

-- inject sync points as suggested for repro
rm -rf bld/
mkdir bld && cd bld
rm -rf CMakeCache.txt
cmake-3.14.4/bin/cmake .. -DCMAKE_BUILD_TYPE=Debug -DCMAKE_INSTALL_PREFIX=$PWD -DWITH_BOOST=<path>/boost 

make -j32
make install

- there was "NUL" issue in the mtr at the end of the test and hence hardcoded tx isolation

./mtr bug
Logging: ./mtr  bug
MySQL Version 5.7.29
.
.
==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
SET @saved_global_isolation= @@global.transaction_isolation;
SET @@global.transaction_isolation= 'READ-COMMITTED';
create table t(id int primary key, k varchar(1024), status int, key k1(k)) charset=latin1;
.
.
.
set session debug="-d, compare_end_range";
set session debug="-d, sleep_after_mtr_commit";
SET @@global.transaction_isolation= 'REPEATABLE-READ';
drop table t;
[100%] main.bug                                 [ pass ]  26255
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 26.255 of 33 seconds executing testcases

Completed: All 1 tests were successful.

regards,
Umesh
[20 Apr 2020 9:05] zkong kong
Hello Umesh Shastry:

En ... the mtr make the prev_rec point to a invalid beginning of a record. According to
the code in rec_get_offsets_func, it's not crash every time.

switch (UNIV_EXPECT(rec_get_status(rec),
                    REC_STATUS_ORDINARY)) {
        case REC_STATUS_ORDINARY:
            n = dict_index_get_n_fields(index);
            break;
        case REC_STATUS_NODE_PTR:
            /* Node pointer records consist of the
            uniquely identifying fields of the record
            followed by a child page number field. */
            n = dict_index_get_n_unique_in_tree_nonleaf(index) + 1;
            break;
        case REC_STATUS_INFIMUM:
        case REC_STATUS_SUPREMUM:
            /* infimum or supremum record */
            n = 1;
            break;
        default:
            ut_error;
            return(NULL);
        }

Please run mtr with --manual-gdb
and set a breakpoint at row0sel.cc:5230 to check the prev_rec.

Breakpoint 2, row_search_mvcc (buf=0x2aaaf00175f0 "�", mode=PAGE_CUR_GE, prebuilt=0x2aaaf000e4c0, match_mode=1, direction=0)
    at /u01/kongzhi.kz/mysql-servers/mysql-5.7.29/storage/innobase/row/row0sel.cc:5230
5230				offsets = rec_get_offsets(prev_rec, prebuilt->index,
(gdb) p prev_rec
$1 = (const rec_t *) 0x2aaab91c7bba "387838783878387838783878387838783878387838783878387838783878387838783878387838783878387838783878387838783878387838783878387838783878387838\200"
[20 Apr 2020 10:05] MySQL Verification Team
Thank you for the details, I'll give it a try and let you know if I face any further issues.

regards,
Umesh
[21 Apr 2020 12:16] MySQL Verification Team
Thank you for the report and feedback.
I tried exact steps but even after 10+ attempts didn't notice crash but with --manual-gdb option with mtr and after setting the break-point as suggested and observed prev_rec pointing to an invalid beginning of a record. Joining the activity log shortly.

regards,
Umesh
[21 Apr 2020 12:18] MySQL Verification Team
Test results - 5.7.29

Attachment: 99286_5.7.29.results (application/octet-stream, text), 276.54 KiB.

[20 Oct 2020 6:00] MySQL Verification Team
Per internal closure notes - Fixed as of the upcoming 5.7.32, 8.0.22 release, and here's the proposed
changelog entry from the documentation team:

A failure occurred during a concurrent update operation. The failure was
due to an invalid previous record value.