MySQL Bugs: #75736: DEADLOCK of threads detected! 5.7.5, 1 thread SQL testcase, sporadic, in ib

Bug #75736	DEADLOCK of threads detected! 5.7.5, 1 thread SQL testcase, sporadic, in ib_logf
Submitted:	3 Feb 2015 2:07	Modified:	24 Apr 2015 12:40
Reporter:	Roel Van de Paar	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: DML	Severity:	S1 (Critical)
Version:	5.7.5-m15, 5.7.6	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
2015-02-03T01:49:55.394733Z 0 [Note] /sda/MS-mysql-5.7.5-m15-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.7.5-m15-debug'  socket: '/dev/shm/1422599810/socket.sock'  port: 33653  MySQL Community Server (GPL)
2015-02-03T01:49:55.394761Z 1 [Note] Event Scheduler: scheduler thread started with id 1
########################################
DEADLOCK of threads detected!
rw-lock 0x7f04adac16a8 --Thread 139658025486080 has waited at ibuf0ibuf.cc line 4691 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7f04adac16a8 created in file buf0buf.cc line 1209
a writer (thread id 139658707420928) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: ffffffffe0000000
Last time read locked in file ibuf0ibuf.cc line 2567
Last time write locked in file /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc line 1798
Locked: thread 139658707420928 file /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc line 1798  X-LOCK
rw-lock 0x7f04adabe228 --Thread 139658707420928 has waited at btr0cur.cc line 1798 for 0.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f04adabe228 created in file buf0buf.cc line 1209
a writer (thread id 139658707420928) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffffffffffe
Last time read locked in file ibuf0ibuf.cc line 4691
Last time write locked in file /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc line 1798
Locked: thread 139658025486080 file /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ibuf/ibuf0ibuf.cc line 4691  S-LOCK
Locked: thread 139658025486080 file /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ibuf/ibuf0ibuf.cc line 4691  S-LOCK
2015-02-03T01:53:56.284786Z 13 [ERROR] [FATAL] InnoDB: ########################################
Deadlock Detected!
2015-02-03 12:53:56 0x7f04d3a54700  InnoDB: Assertion failure in thread 139658707420928 in file ha_innodb.cc line 17770
InnoDB: We intentionally generate a memory trap.

How to repeat:
$ vi 1422599810_mybase     # Update base path in this file (the only change required!)
$ ./1422599810_init        # Initializes the data dir
$ ./1422599810_start       # Starts mysqld
$ ./1422599810_cl          # To check mysqld is up
$ while(true); do ./1422599810_run; done   # Run the testcase in a loop (produces output). Likely < 10 loops required, but... it is sporadic so system differences may improve/worsen reproducibility
$ vi /dev/shm/1422599810/error.log.out  # Verify the error log
$ ./1422599810_gdb         # Brings you to a gdb prompt
$ ./1422599810_parse_core  # Create {epoch}_STD.gdb and {epoch}_FULL.gdb; standard and full var gdb stack traces
etc.

Thread 1 (Thread 0x7f04d3a54700 (LWP 8632)):
#0  0x00007f04d349c771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e15cd8 in my_write_core (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/mysys/stacktrace.c:247
#2  0x0000000000822044 in handle_fatal_signal (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x00007f04d20a05c9 in raise () from /lib64/libc.so.6
#5  0x00007f04d20a1cd8 in abort () from /lib64/libc.so.6
#6  0x00000000010d4a9b in ut_dbg_assertion_failed (expr=0x0, file=0x1483768 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc", line=17770) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ut/ut0dbg.cc:68
#7  0x0000000000f231dd in ib_logf (level=IB_LOG_LEVEL_FATAL, format=0x14dbcc0 '#' <repeats 40 times>, "\nDeadlock Detected!") at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc:17770
#8  0x000000000108a31a in sync_array_wait_event (arr=0x7f04d141e610, cell=@0x7f04d3a4b1f8: 0x7f04b4f58150) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/sync/sync0arr.cc:446
#9  0x000000000108d35b in rw_lock_x_lock_wait_func (lock=0x7f04adabe228, pass=0, threshold=0, file_name=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/sync/sync0rw.cc:513
#10 0x000000000108d45f in rw_lock_x_lock_low (lock=0x7f04adabe228, pass=0, file_name=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/sync/sync0rw.cc:560
#11 0x000000000108d885 in rw_lock_x_lock_func (lock=0x7f04adabe228, pass=0, file_name=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/sync/sync0rw.cc:727
#12 0x0000000001127e54 in pfs_rw_lock_x_lock_func (lock=0x7f04adabe228, pass=0, file_name=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/include/sync0rw.ic:739
#13 0x0000000001136419 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10, file=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798, mtr=0x7f04d3a4e840, dirty_with_no_latch=false) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/buf/buf0buf.cc:4390
#14 0x00000000010fcc14 in btr_block_get_func (page_id=..., page_size=..., mode=2, file=0x14f48b8 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc", line=1798, index=0x7f04b63d7c98, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/include/btr0btr.ic:63
#15 0x00000000011022c4 in btr_cur_search_to_nth_level (index=0x7f04b63d7c98, level=2, tuple=0x7f049d047a98, mode=4, latch_mode=34, cursor=0x7f04d3a4c870, has_search_latch=0, file=0x14ef688 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc", line=2225, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc:1798
#16 0x00000000010ece37 in btr_insert_on_non_leaf_level_func (flags=7, index=0x7f04b63d7c98, level=2, tuple=0x7f049d047a98, file=0x14ef688 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc", line=2225, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2072
#17 0x00000000010ed5a5 in btr_attach_half_pages (flags=7, index=0x7f04b63d7c98, block=0x7f04adac1550, split_rec=0x7f049d14eedd "", new_block=0x7f04adae1878, direction=111, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2225
#18 0x00000000010ee89e in btr_page_split_and_insert (flags=7, cursor=0x7f04d3a4d780, offsets=0x7f04d3a4e298, heap=0x7f04d3a4e2a0, tuple=0x7f049d047098, n_ext=0, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2628
#19 0x0000000001105efa in btr_cur_pessimistic_insert (flags=7, cursor=0x7f04d3a4d780, offsets=0x7f04d3a4e298, heap=0x7f04d3a4e2a0, entry=0x7f049d047098, rec=0x7f04d3a4e2a8, big_rec=0x7f04d3a4e2b0, n_ext=0, thr=0x0, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc:3382
#20 0x00000000010ecfb6 in btr_insert_on_non_leaf_level_func (flags=3, index=0x7f04b63d7c98, level=1, tuple=0x7f049d047098, file=0x14ef688 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc", line=2225, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2104
#21 0x00000000010ed5a5 in btr_attach_half_pages (flags=3, index=0x7f04b63d7c98, block=0x7f04adac6de8, split_rec=0x7f049d03da9c "", new_block=0x7f04adacdd78, direction=111, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2225
#22 0x00000000010ee89e in btr_page_split_and_insert (flags=3, cursor=0x7f04d3a4e750, offsets=0x7f04d3a4f238, heap=0x7f04d3a4f240, tuple=0x7f049d047f98, n_ext=0, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0btr.cc:2628
#23 0x0000000001105efa in btr_cur_pessimistic_insert (flags=3, cursor=0x7f04d3a4e750, offsets=0x7f04d3a4f238, heap=0x7f04d3a4f240, entry=0x7f049d047f98, rec=0x7f04d3a4f228, big_rec=0x7f04d3a4f248, n_ext=0, thr=0x7f049d14d7d8, mtr=0x7f04d3a4e840) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc:3382

#24 0x0000000000f606f3 in ibuf_insert_low (mode=32801, op=IBUF_OP_INSERT, no_counter=0, entry=0x7f049d19f3e0, entry_size=16, index=0x7f049d05f498, page_id=...,page_size=..., thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ibuf/ibuf0ibuf.cc:3714
#25 0x0000000000f60d04 in ibuf_insert (op=IBUF_OP_INSERT, entry=0x7f049d19f3e0, index=0x7f049d05f498, page_id=..., page_size=..., thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ibuf/ibuf0ibuf.cc:3904
#26 0x00000000011005e6 in btr_cur_search_to_nth_level (index=0x7f049d05f498, level=0, tuple=0x7f049d19f3e0, mode=4, latch_mode=2, cursor=0x7f04d3a503b0, has_search_latch=0, file=0x14b8cd0 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc", line=2864, mtr=0x7f04d3a50760) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/btr/btr0cur.cc:1108
#27 0x00000000010007a9 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x7f049d05f498, offsets_heap=0x7f049d048410, heap=0x7f049d046610, entry=0x7f049d19f3e0, trx_id=0, thr=0x7f049d14d7d8, dup_chk_only=false) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:2864
#28 0x0000000001001975 in row_ins_sec_index_entry (index=0x7f049d05f498, entry=0x7f049d19f3e0, thr=0x7f049d14d7d8, dup_chk_only=false) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:3262
#29 0x0000000001001af4 in row_ins_index_entry (index=0x7f049d05f498, entry=0x7f049d19f3e0, thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:3308
#30 0x0000000001001f3b in row_ins_index_entry_step (node=0x7f049d14d590, thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:3448
#31 0x00000000010022cc in row_ins (node=0x7f049d14d590, thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:3590
#32 0x0000000001002829 in row_ins_step (thr=0x7f049d14d7d8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0ins.cc:3762
#33 0x000000000101d8fd in row_insert_for_mysql_using_ins_graph (mysql_rec=0x7f049d061338 <incomplete sequence \375>, prebuilt=0x7f049d14d098) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0mysql.cc:1579
#34 0x000000000101dc4c in row_insert_for_mysql (mysql_rec=0x7f049d061338 <incomplete sequence \375>, prebuilt=0x7f049d14d098) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/row/row0mysql.cc:1695
#35 0x0000000000f1139a in ha_innobase::write_row (this=0x7f049d061020, record=0x7f049d061338 <incomplete sequence \375>) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc:6755
#36 0x000000000088caba in handler::ha_write_row (this=0x7f049d061020, buf=0x7f049d061338 <incomplete sequence \375>) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/handler.cc:7423
#37 0x0000000000d1a9b5 in write_record (thd=0x7f049d01c000, table=0x7f049d098810, info=0x7f04d3a51960, update=0x7f04d3a519e0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_insert.cc:1679
#38 0x0000000000d18329 in mysql_insert (thd=0x7f049d01c000, table_list=0x7f049d0279c0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_insert.cc:707
#39 0x0000000000b49cd5 in mysql_execute_command (thd=0x7f049d01c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:3367
#40 0x0000000000b4fcc1 in mysql_parse (thd=0x7f049d01c000, parser_state=0x7f04d3a52e60) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:5427
#41 0x0000000000b44814 in dispatch_command (command=COM_QUERY, thd=0x7f049d01c000, packet=0x7f049d07d011 "INSERT INTO t1 VALUES (CONVERT(_ucs2 0x064A062706310634062706370631 USING utf8))", packet_length=80) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:1250
#42 0x0000000000b4354d in do_command (thd=0x7f049d01c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:834
#43 0x0000000000c4d4ce in handle_connection (arg=0x7f04c0b5a180) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#44 0x0000000000e394b8 in pfs_spawn_thread (arg=0x7f04b5bf8d50) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/perfschema/pfs.cc:2137
#45 0x00007f04d3497df3 in start_thread () from /lib64/libpthread.so.0
#46 0x00007f04d21611ad in clone () from /lib64/libc.so.6

Bug bundle with all scripts listed above

Attachment: 1422599810_bug_bundle.tar.gz (application/gzip, text), 93.30 KiB.

Hello Roel,

Thank you for the report and test case.
Confirmed that 5.7.6 debug build is affected.

Thanks,
Umesh

test results

Attachment: 75736..txt (text/plain), 16.41 KiB.

I copied the variables from the test files and started the server like so:

bin/mysqld --skip-grant-tables --innodb_buffer_pool_size=5242880
--innodb_buffer_pool_instances=1 --innodb_old_blocks_time=1000
--event-scheduler=ON --maximum-bulk_insert_buffer_size=1M
--maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M
--maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M
--maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M
--maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M
--maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M
--maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M
--maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M
--maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M
--maximum-transaction_prealloc_size=1M --log-output=none
--sql_mode=ONLY_FULL_GROUP_BY --event-scheduler=ON

Rand the test like so:
while :; do mysql -u root < 1422599810.sql ; done

It didn't crash for me in one hour. The version tested was the current 5.7 HEAD.

Scratch the previous comment, my default ~/.my.cnf has --innodb-change-buffer=none. I specified the --innodb-change-buffer=all on the mysqld command line and it crashes as described in the bug report.

Sunny, thanks, but, for the future, why not use the test case as given? The only thing needed is to update base directory in _mybase (assuming you are using a binary tarball (./scripts/make_binary_distribution) build offcourse) and then you can run ./init > ./start > ./run - very easy. Takes a few minutes to build tarball once you have build source dir.

Roel, because I like to understand why a certain config is required. I prefer to run the server with the minimal configuration required to reproduce the bug. In this case I simply forgot to disable the defaults config file.

Sunny, understand. As long as the submitted testcases is eval'ed before stating the issue is not reproducible.

Roel, that was already done by Umesh, but on an older version than the one I was testing. Sometimes bugs are fixed in the latest version.

Yes, and confirmation of the same can be done once the posted testcase is used.

Fixed as of the upcoming 5.7.8 release, and here's the changelog entry:

In debug builds, enabling the "btr_cur_limit_optimistic_insert_debug"
flag raised a deadlock exception in the change buffer clustered index.

Thank you for the bug report.