MySQL Bugs: #71768: debug assert during InnoDB secondary index access

Bug #71768	debug assert during InnoDB secondary index access
Submitted:	19 Feb 2014 8:43	Modified:	9 Mar 2018 13:24
Reporter:	Seppo Jaakola	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB Plugin storage engine	Severity:	S3 (Non-critical)
Version:	5.5.36	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Running a debug source build of MySQL server 5.5.36, I hit this assert:

Version: '5.5.36-debug'  socket: '/home/seppo/work/testing/node1-shm/mysql/var/mysqld.sock'  port: 3307  Source distribution
140219  9:57:04  InnoDB: Assertion failure in thread 140458047309568 in file row0sel.c line 2725
InnoDB: Failing assertion: !rec_get_deleted_flag(rec, rec_offs_comp(offsets))
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
07:57:04 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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.

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

Thread pointer: 0x44b6680
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 = 7fbef003fe50 thread_stack 0x40000
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(my_print_stacktrace+0x38)[0x8d2118]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(handle_fatal_signal+0x3f7)[0x757582]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfbb0)[0x7fbef371dbb0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7fbef2f3ff77]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7fbef2f435e8]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x940424]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x94205b]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x9113f9]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_ZN7handler14index_read_mapEPhPKhm16ha_rkey_function+0x66)[0x762264]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_ZN7handler18index_read_idx_mapEPhjPKhm16ha_rkey_function+0x6f)[0x7606cf]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x635a2a]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x6355c4]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x61e60e]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_ZN4JOIN8optimizeEv+0xbac)[0x6174b8]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x2d7)[0x61d077]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z13handle_selectP3THDP3LEXP13select_resultm+0x199)[0x615021]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native[0x5efba8]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z21mysql_execute_commandP3THD+0x9e7)[0x5e884d]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z11mysql_parseP3THDPcjP12Parser_state+0x20c)[0x5f1db7]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z16dispatch_command19enum_server_commandP3THDPcj+0xae8)[0x5e5e09]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z10do_commandP3THD+0x293)[0x5e5111]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(_Z24do_handle_one_connectionP3THD+0x191)[0x6d092a]
/home/seppo/work/testing/node1-shm/mysql/sbin/mysqld.native(handle_one_connection+0x33)[0x6d0470]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7f6e)[0x7fbef3715f6e]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fbef30039cd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fbea80140d0): is an invalid pointer
Connection ID (thread ID): 1903
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file

I have core files and general query logs for this issue. It is even possible to enable  btr_cur_print_record_ops and still make this problem to surface.

How to repeat:
I hit this issue with Galera Cluster performance test tool (sqlgen), but I have seen similar stack traces from sysbench testing also. You will need a table both with primary key and unique key, and *high* rate of DML with *high* conflict rate, against that table.
In my tests, I use 8 client connections and 16 rows. Running the tester and mysql server in my laptop, I can reproduce the issue with MySQL 5.5.36 in few seconds.

With MySQL 5.5.16, reproducing takes much longer, ~400 secs.

Suggested fix:
Analyze if the delete flagged row would really be returned to client, if this assert is ignored.

I also got this problem when I use sysbench(oltp) to do a test on the debug version of mysql-5.5.36, the backtrace like blew:

#0  __pthread_kill (threadid=<optimized out>, signo=<optimized out>, signo@entry=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  0x00000000008394c8 in my_write_core (sig=6) at /home/root/trunk/mysql-5.5.30/mysys/stacktrace.c:433
#2  0x000000000070a1c0 in handle_fatal_signal (sig=6) at /home/root/trunk/mysql-5.5.30/sql/signal_handler.cc:247
#3  <signal handler called>
#4  0x00007f4caa6c9475 in *__GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  0x00007f4caa6cc6f0 in *__GI_abort () at abort.c:92
#6  0x00000000008954a9 in row_sel_store_mysql_rec (mysql_rec=mysql_rec@entry=0x7f4c07449410 "\377y\177<", prebuilt=prebuilt@entry=0x7f4c07459078, 
    rec=rec@entry=0x7f4c4b3d6ff7 "", rec_clust=rec_clust@entry=0, offsets=0x7f4c48d79230)
    at /home/root/trunk/mysql-5.5.30/storage/innobase/row/row0sel.c:2722
#7  0x000000000089a597 in row_search_for_mysql (buf=0x7f4c07449410 "\377y\177<", mode=2, prebuilt=0x7f4c07459078, match_mode=1, direction=0)
    at /home/root/trunk/mysql-5.5.30/storage/innobase/row/row0sel.c:3699
#8  0x000000000085e65e in ha_innobase::index_read (this=0x7f4c07447010, buf=0x7f4c07449410 "\377y\177<", key_ptr=<optimized out>, key_len=4, 
    find_flag=<optimized out>) at /home/root/trunk/mysql-5.5.30/storage/innobase/handler/ha_innodb.cc:6125
#9  0x000000000071385b in handler::index_read_map (this=0x7f4c07447010, buf=0x7f4c07449410 "\377y\177<", key=0x7f4c01422278 "\245\016=", keypart_map=<optimized out>, 
    find_flag=HA_READ_KEY_EXACT) at /home/root/trunk/mysql-5.5.30/sql/handler.h:1919
#10 0x000000000070a7ec in handler::index_read_idx_map (this=0x7f4c07447010, buf=0x7f4c07449410 "\377y\177<", index=<optimized out>, key=0x7f4c01422278 "\245\016=", 
    keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /home/root/trunk/mysql-5.5.30/sql/handler.cc:5038
#11 0x00000000006266f1 in join_read_const (tab=tab@entry=0x7f4c01421da8) at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:12290
#12 0x000000000062697b in join_read_const_table (tab=tab@entry=0x7f4c01421da8, pos=pos@entry=0x7f4c014750a0)
    at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:12192
#13 0x000000000062ac26 in make_join_statistics (join=join@entry=0x7f4c01475010, tables_arg=0x7f4c01421210, conds=0x7f4c01421b98, 
    keyuse_array=keyuse_array@entry=0x7f4c014765c8) at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:3002
#14 0x000000000062e179 in JOIN::optimize (this=this@entry=0x7f4c01475010) at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:1058
#15 0x00000000006315b1 in mysql_select (thd=thd@entry=0x7f4c3f3d6000, rref_pointer_array=rref_pointer_array@entry=0x7f4c3f3d8be0, tables=0x7f4c01421210, wild_num=0, 
    fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=select_options@entry=2148797184, 
    result=result@entry=0x7f4c01421ac8, unit=unit@entry=0x7f4c3f3d83e8, select_lex=select_lex@entry=0x7f4c3f3d8a08)
    at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:2591
#16 0x0000000000637583 in handle_select (thd=0x7f4c3f3d6000, lex=0x7f4c3f3d8338, result=0x7f4c01421ac8, setup_tables_done_option=<optimized out>)
    at /home/root/trunk/mysql-5.5.30/sql/sql_select.cc:298
#17 0x00000000005ea614 in execute_sqlcom_select (thd=thd@entry=0x7f4c3f3d6000, all_tables=0x7f4c01421210)
    at /home/root/trunk/mysql-5.5.30/sql/sql_parse.cc:4876
#18 0x00000000005f0b96 in mysql_execute_command (thd=thd@entry=0x7f4c3f3d6000) at /home/root/trunk/mysql-5.5.30/sql/sql_parse.cc:2246
#19 0x00000000005f7bb6 in mysql_parse (thd=thd@entry=0x7f4c3f3d6000, rawbuf=<optimized out>, length=38, parser_state=parser_state@entry=0x7f4c48d7b6f0)
    at /home/root/trunk/mysql-5.5.30/sql/sql_parse.cc:5918
---Type <return> to continue, or q <return> to quit--- 
#20 0x00000000005f8618 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f4c3f3d6000, 
    packet=packet@entry=0x7f4c3f3da001 "SELECT c FROM sbtest1 WHERE id=4001445", packet_length=packet_length@entry=38)
    at /home/root/trunk/mysql-5.5.30/sql/sql_parse.cc:1108
#21 0x00000000005f9b71 in do_command (thd=0x7f4c3f3d6000) at /home/root/trunk/mysql-5.5.30/sql/sql_parse.cc:833
#22 0x00000000006a1eb2 in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f4c3f3d6000)
    at /home/root/trunk/mysql-5.5.30/sql/sql_connect.cc:935
#23 0x00000000006a1f83 in handle_one_connection (arg=0x7f4c3f3d6000) at /home/root/trunk/mysql-5.5.30/sql/sql_connect.cc:849
#24 0x00007f4cab3ebb50 in start_thread (arg=<optimized out>) at pthread_create.c:304
#25 0x00007f4caa771a7d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#26 0x0000000000000000 in ?? ()

From the backtrace, you can see that a select(SELECT c FROM sbtest1 WHERE id=4001445) cause this problem. Then I use mysqlbinlog to find what happens on the record with id=4001445, last sql like blew:

DELETE FROM sbtest1 WHERE id=4001445
INSERT INTO sbtest1 (id, k, c, pad) VALUES (4001445, 3966540, '36190505929-84866323743-19386592756-45157300342-95221964258-39194550156-39982223010-33274356149-97729777598-94780230128', '94043513913-76045436617-36300622759-63185209519-77295099218') 

after doing above, a new record with id=4001445 inserted, but the select failed, cause this problem.

Hi,

Thank you for your bug report.

Truthfully, we have never seen a backtrace like this one. Hence , we need a fully repeatable test case in order to be able to verify the bug. Hence, dump of all tables involved in this crash, plus the statement that produced the error.

You should also know that this kind of error can occur due to hardware errors or due to the temporary glitches in the RAM modules. If you use ECC DDR4 RAM modules, two bits checking one bit correcting, with some high quality RAID or SSD, then that is not your problem.

In order to find the command that produced the crash, do note that it is happening in a SELECT query with a join.

If you do not succeed in getting us the data that we require in order to verify the bug, please consider running a debug binary and setting the OS and MySQL server so that a core file is produced. If you manage to repeat the crash with that join and you obtain a core file, please, let us know.

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".

These are all fixed.  Consider a newer version of MySQL.
Bug 14668683 - ASSERT REC_GET_DELETED_FLAG(REC, PAGE_IS_COMP(PAGE)) 
Bug 11765588 - UT_AD ASSERT REC_GET_DELETED_FLAG(REC, PAGE_IS_COMP(PAGE)) 
Bug 14636528 - INNODB CHANGE BUFFERING IS NOT ENTIRELY CRASH-SAFE