MySQL Bugs: #59225: Deadlock between DML and innodb_adaptive_hash

Bug #59225	Deadlock between DML and innodb_adaptive_hash_index=OFF
Submitted:	30 Dec 2010 0:43	Modified:	10 Feb 2011 23:41
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6.1-m5	OS:	Any
Assigned to:	Jimmy Yang	CPU Architecture:	Any

Description:
Several threads perform DML operations (insert and delete) on an InnoDB table, while one more thread regularly changes the value of innodb_adaptive_hash_index. At some point, server hangs -- it does not accept new connections, and for an existing connection most of further operations hang (SHOW PROCESSLIST works, but SHOW ENGINE INNODB STATUS, SELECT etc. do not).

The stress test is attached. The problem is more easily reproducible on a debug version (I tried trunk-bugfixing), but happens on release builds also.
It is faster to reproduce it with a greater number of DML threads, although I had it with only one insert and one delete thread (it took several hours).

In the attached test, the frequency of innodb_adaptive_hash_index change is increased in order to get the deadlock faster. In usual stress test, it happens once in 10 minutes, and still most of 2-hour test runs hit the problem

Stack trace is attached.

How to repeat:
- unpack the attached archive in <mysql-basedir>/mysql-test. It should create
'stress_test_basedir' folder;
- on Linux/Solaris, run as
perl ./stress_test_basedir/run.pl

run.pl is a wrapper for MTR to start server, and mysql-stress-test
to run a multi-thread stress test.
Please use perl ./stress_test_basedir/run.pl --help command to see available options.

Important note:
For mysql-stress-test you need to have perl with threads on the top of your path.

Notes:
Default parameters for the test are 15 insert threads, 15 delete threads, 1 innodb_adaptive_hash_index thread. On release builds and/or fast machines, you might want to increase the number of DML threads. It can be done via the command-line option:
--threads=20,20,1

By default the test starts MySQL server on port 13100. If you want to run it on your previously started server, use the command-line option:
--skip-server-start

You can also provide a non-default port number:
--port=<port number>

STDOUT/STDERR should contain usual MTR output for server startup
(unless you chose to skip server start), then briefly go through
preparation/initialization/configuration stages,
and then start rapidly producing lines like

not ok
test_loop[0:0 0:84]: TID 1 test: 'stress2' Errors: Severity S5: 1

test_loop[0:0 0:85]: TID 4 test: 'stress1' Errors: No Errors. Test Passed OK

main: Thread ID 6 TID 6 started
ok
test_loop[0:0 0:86]: TID 3 test: 'stress1' Errors: No Errors. Test Passed OK

etc.

If the deadlock is reached, the output stops. Usually if there are enough DML threads, it happens in several minutes.

If there is no deadlock, then by default the test will run for an hour and will stop having said something about INT signal received.

Stress test

Attachment: 59225_stress_test.tar.gz (application/gzip, text), 37.30 KiB.

gdb bt output

Attachment: 59225_threads.out (application/octet-stream, text), 52.78 KiB.

There is a self deadlock:

--Thread 2651892592 has waited at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c line 2018 for 261.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0xa41749e8 created in file /home/jy/work/nextmr/mr/storage/innobase/buf/buf0buf.c line 906
a writer (thread id 2651892592) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file /home/jy/work/nextmr/mr/storage/innobase/btr/btr0cur.c line 3383
Last time write locked in file /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c line 2018

Thread 2651892592 has following stack:

Thread 24 (Thread 0x9e10ab70 (LWP 29768)):
#0  0x00532422 in __kernel_vsyscall ()
#1  0x002b0e15 in pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:122
#2  0x084eecab in safe_cond_wait (cond=0xa4a5244, mp=0xa4a51f8, 
    file=0x88d0390 "/home/jy/work/nextmr/mr/storage/innobase/os/os0sync.c", 
    line=207) at /home/jy/work/nextmr/mr/mysys/thr_mutex.c:240
#3  0x086da73a in os_cond_wait (cond=0xa4a5244, mutex=0xa4a51f8)
    at /home/jy/work/nextmr/mr/storage/innobase/os/os0sync.c:207
#4  0x086daea6 in os_event_wait_low (event=0xa4a51f8, reset_sig_count=94)
---Type <return> to continue, or q <return> to quit---
    at /home/jy/work/nextmr/mr/storage/innobase/os/os0sync.c:634
#5  0x085dbac6 in sync_array_wait_event (arr=0xa0ed7d8, index=8)
    at /home/jy/work/nextmr/mr/storage/innobase/sync/sync0arr.c:457
#6  0x085dd113 in rw_lock_x_lock_wait (lock=0xa41749e8, 
    file_name=0x88d9fa8 "/home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c", line=2018) at /home/jy/work/nextmr/mr/storage/innobase/sync/sync0rw.c:529
#7  0x085dd1eb in rw_lock_x_lock_low (lock=0xa41749e8, pass=0, 
    file_name=0x88d9fa8 "/home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c", line=2018) at /home/jy/work/nextmr/mr/storage/innobase/sync/sync0rw.c:572
#8  0x085dd2d4 in rw_lock_x_lock_func (lock=0xa41749e8, pass=0, 
    file_name=0x88d9fa8 "/home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c", line=2018) at /home/jy/work/nextmr/mr/storage/innobase/sync/sync0rw.c:628
#9  0x0863adf2 in buf_page_get_gen (space=0, zip_size=0, offset=674, 
    rw_latch=2, guess=0x0, mode=11, 
    file=0x88d9fa8 "/home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c", 
    line=2018, mtr=0x9e1072d0)
    at /home/jy/work/nextmr/mr/storage/innobase/buf/buf0buf.c:3321
#10 0x0861c608 in btr_cur_search_to_nth_level (index=0xab95d80, level=0, 
    tuple=0x9e208bf8, mode=4, latch_mode=2, cursor=0x9e10725c, 
    has_search_latch=0, 
    file=0x88d9fa8 "/home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c", 
    line=2018, mtr=0x9e1072d0)
    at /home/jy/work/nextmr/mr/storage/innobase/btr/btr0cur.c:574
#11 0x0870eb9e in row_ins_index_entry_low (mode=2, index=0xab95d80, 
    entry=0x9e208bf8, n_ext=0, thr=0xad5dcf8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c:2016
#12 0x0870f263 in row_ins_index_entry (index=0xab95d80, entry=0x9e208bf8, 
    n_ext=0, foreign=1, thr=0xad5dcf8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c:2188
#13 0x0870f574 in row_ins_index_entry_step (node=0xad5db58, thr=0xad5dcf8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c:2273
#14 0x0870f7d4 in row_ins (node=0xad5db58, thr=0xad5dcf8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c:2405
#15 0x0870fa51 in row_ins_step (thr=0xad5dcf8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0ins.c:2515
#16 0x085afdc9 in row_insert_for_mysql (mysql_rec=0xac8b9f0 "\341\f", 
    prebuilt=0xad017a8)
    at /home/jy/work/nextmr/mr/storage/innobase/row/row0mysql.c:1201
#17 0x08588a1b in ha_innobase::write_row (this=0xac8b830, 
    record=0xac8b9f0 "\341\f")
    at /home/jy/work/nextmr/mr/storage/innobase/handler/ha_innodb.cc:5414
#18 0x08354aba in handler::ha_write_row (this=0xac8b830, 
    buf=0xac8b9f0 "\341\f") at /home/jy/work/nextmr/mr/sql/handler.cc:5836
#19 0x081eac53 in write_record (thd=0xa1187c28, table=0xac8cda8, 
    info=0x9e107abc) at /home/jy/work/nextmr/mr/sql/sql_insert.cc:1734
#20 0x081e8df4 in mysql_insert (thd=0xa1187c28, table_list=0xaf36d38,
    fields=..., values_list=..., update_fields=..., update_values=..., 
    duplic=DUP_ERROR, ignore=false)
    at /home/jy/work/nextmr/mr/sql/sql_insert.cc:928
#21 0x08200997 in mysql_execute_command (thd=0xa1187c28)
    at /home/jy/work/nextmr/mr/sql/sql_parse.cc:2834
#22 0x0841e9fd in sp_instr_stmt::exec_core (this=0xb33c3a8, thd=0xa1187c28, 
    nextp=0x9e108bb0) at /home/jy/work/nextmr/mr/sql/sp_head.cc:3165
#23 0x0841e28d in sp_lex_keeper::reset_lex_and_exec_core (this=0xb33c3d0, 
    thd=0xa1187c28, nextp=0x9e108bb0, open_tables=false, instr=0xb33c3a8)
    at /home/jy/work/nextmr/mr/sql/sp_head.cc:2959
#24 0x0841e7d7 in sp_instr_stmt::execute (this=0xb33c3a8, thd=0xa1187c28, 
    nextp=0x9e108bb0) at /home/jy/work/nextmr/mr/sql/sp_head.cc:3097
#25 0x0841a78b in sp_head::execute (this=0xb2eefb0, thd=0xa1187c28, 
    merge_da_on_success=true) at /home/jy/work/nextmr/mr/sql/sp_head.cc:1417
#26 0x0841c506 in sp_head::execute_procedure (this=0xb2eefb0, thd=0xa1187c28, 
    args=0xa1189620) at /home/jy/work/nextmr/mr/sql/sp_head.cc:2173
#27 0x082046d0 in mysql_execute_command (thd=0xa1187c28)
    at /home/jy/work/nextmr/mr/sql/sql_parse.cc:3950
#28 0x082083a0 in mysql_parse (thd=0xa1187c28, 
    rawbuf=0xb27eff8 "CALL ins_tb5_eng1 (@tmp_num, @tmp_word)", length=39, 
    parser_state=0x9e109b44) at /home/jy/work/nextmr/mr/sql/sql_parse.cc:5537
#29 0x081fc586 in dispatch_command (command=COM_QUERY, thd=0xa1187c28, 
    packet=0xa11f6061 "CALL ins_tb5_eng1 (@tmp_num, @tmp_word)",

Pushed into mysql-trunk 5.6.2 (revid:vasil.dimov@oracle.com-20110130165639-1pr3opz839b98q5j) (version source revid:vasil.dimov@oracle.com-20110130165522-m0o6al0pn5ig9kv3) (merge vers: 5.6.2) (pib:24)