[MDEV-5792] Deadlock between SELECTs from METADATA_LOCK_INFO and another I_S table - JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0.8
Fix Version/s: 10.0.11
Component/s: None
Labels:
None

Description

One thread repeatedly executes SELECT * FROM INFORMATION_SCHEMA.METADATA_LOCK_INFO, another one SELECT * FROM INFORMATION_SCHEMA.TABLES.

Soon after the start both threads freeze:

+----+------+-----------------+-------+---------+------+----------------+-----------------------------------------------------+----------+
| Id | User | Host            | db    | Command | Time | State          | Info                                                | Progress |
+----+------+-----------------+-------+---------+------+----------------+-----------------------------------------------------+----------+
|  2 | root | localhost:34518 | mysql | Sleep   |  486 |                | NULL                                                |    0.000 |
|  6 | root | localhost:34522 | test  | Query   |  484 | Opening tables | SELECT * FROM INFORMATION_SCHEMA.TABLES             |    0.000 |
|  7 | root | localhost:34523 | test  | Query   |  484 | executing      | SELECT * FROM INFORMATION_SCHEMA.METADATA_LOCK_INFO |    0.000 |
|  9 | root | localhost:34532 | test  | Query   |    0 | init           | show full processlist                               |    0.000 |
+----+------+-----------------+-------+---------+------+----------------+-----------------------------------------------------+----------+

Thread 3 (Thread 0x7f1238ac7700 (LWP 19689)):
#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007f1238757339 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007f123875715b in __pthread_mutex_lock (mutex=0x7f12333d20b8) at pthread_mutex_lock.c:61
#3  0x0000000000e06ab2 in safe_mutex_lock (mp=0x7f12333d2090, my_flags=0, file=0xf2c798 "/home/elenst/bzr/10.0/sql/mdl.cc", line=1087) at /home/elenst/bzr/10.0/mysys/t
hr_mutex.c:294
#4  0x0000000000791209 in inline_mysql_mutex_lock (that=0x7f12333d2090, src_file=0xf2c798 "/home/elenst/bzr/10.0/sql/mdl.cc", src_line=1087) at /home/elenst/bzr/10.0/i
nclude/mysql/psi/mysql_thread.h:689
#5  0x00000000007960da in MDL_map_partition::remove (this=0x7f12333d2030, lock=0x7f12333da170) at /home/elenst/bzr/10.0/sql/mdl.cc:1087
#6  0x0000000000792415 in MDL_map::remove (this=0x1831b60, lock=0x7f12333da170) at /home/elenst/bzr/10.0/sql/mdl.cc:1075
#7  0x0000000000792f93 in MDL_lock::remove_ticket (this=0x7f12333da170, list=&MDL_lock::m_granted, ticket=0x7f120c41d670) at /home/elenst/bzr/10.0/sql/mdl.cc:1872
#8  0x0000000000794ced in MDL_context::release_lock (this=0x7f1212adc168, duration=MDL_TRANSACTION, ticket=0x7f120c41d670) at /home/elenst/bzr/10.0/sql/mdl.cc:2837
#9  0x0000000000794e5b in MDL_context::release_locks_stored_before (this=0x7f1212adc168, duration=MDL_TRANSACTION, sentinel=0x0) at /home/elenst/bzr/10.0/sql/mdl.cc:28
87
#10 0x0000000000795248 in MDL_context::rollback_to_savepoint (this=0x7f1212adc168, mdl_savepoint=...) at /home/elenst/bzr/10.0/sql/mdl.cc:3038
#11 0x00000000006f5e39 in fill_schema_table_by_open (thd=0x7f1212adc070, is_show_fields_or_keys=false, table=0x7f120c555088, schema_table=0x1659540, orig_db_name=0x7f1
20c5f19d8, orig_table_name=0x7f120c73a498, open_tables_state_backup=0x7f1238ac4bb0, can_deadlock=false) at /home/elenst/bzr/10.0/sql/sql_show.cc:4249
#12 0x00000000006f7210 in get_all_tables (thd=0x7f1212adc070, tables=0x7f120c4192a8, cond=0x0) at /home/elenst/bzr/10.0/sql/sql_show.cc:4871
#13 0x00000000007047c3 in do_fill_table (thd=0x7f1212adc070, table_list=0x7f120c4192a8, join_table=0x7f120c5f0f18) at /home/elenst/bzr/10.0/sql/sql_show.cc:8066
#14 0x0000000000704b3c in get_schema_tables_result (join=0x7f120c41a860, executed_place=PROCESSED_BY_JOIN_EXEC) at /home/elenst/bzr/10.0/sql/sql_show.cc:8164
#15 0x00000000006ac1f1 in JOIN::exec_inner (this=0x7f120c41a860) at /home/elenst/bzr/10.0/sql/sql_select.cc:2520
#16 0x00000000006ab7d0 in JOIN::exec (this=0x7f120c41a860) at /home/elenst/bzr/10.0/sql/sql_select.cc:2355
#17 0x00000000006aeb4f in mysql_select (thd=0x7f1212adc070, rref_pointer_array=0x7f1212ae06a0, tables=0x7f120c4192a8, wild_num=1, fields=..., conds=0x0, og_num=0, orde
r=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f120c41a840, unit=0x7f1212adfd48, select_lex=0x7f1212ae0428) at /home/elenst/bzr/10.
0/sql/sql_select.cc:3292
#18 0x00000000006a527f in handle_select (thd=0x7f1212adc070, lex=0x7f1212adfc88, result=0x7f120c41a840, setup_tables_done_option=0) at /home/elenst/bzr/10.0/sql/sql_se
lect.cc:372
#19 0x000000000067a251 in execute_sqlcom_select (thd=0x7f1212adc070, all_tables=0x7f120c4192a8) at /home/elenst/bzr/10.0/sql/sql_parse.cc:5301
#20 0x00000000006725fc in mysql_execute_command (thd=0x7f1212adc070) at /home/elenst/bzr/10.0/sql/sql_parse.cc:2587
#21 0x000000000067c9db in mysql_parse (thd=0x7f1212adc070, rawbuf=0x7f120c419088 "SELECT * FROM INFORMATION_SCHEMA.TABLES", length=39, parser_state=0x7f1238ac6630) at 
/home/elenst/bzr/10.0/sql/sql_parse.cc:6447
#22 0x000000000066f7a9 in dispatch_command (command=COM_QUERY, thd=0x7f1212adc070, packet=0x7f1212ae2071 "SELECT * FROM INFORMATION_SCHEMA.TABLES", packet_length=39) a
t /home/elenst/bzr/10.0/sql/sql_parse.cc:1308
#23 0x000000000066eb4b in do_command (thd=0x7f1212adc070) at /home/elenst/bzr/10.0/sql/sql_parse.cc:1005
#24 0x00000000007880ed in do_handle_one_connection (thd_arg=0x7f1212adc070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1379
#25 0x0000000000787e40 in handle_one_connection (arg=0x7f1212adc070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1293
#26 0x0000000000a2cac5 in pfs_spawn_thread (arg=0x7f1212ea3030) at /home/elenst/bzr/10.0/storage/perfschema/pfs.cc:1853

Thread 2 (Thread 0x7f1238a7e700 (LWP 19691)):
#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007f1238757339 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007f123875715b in __pthread_mutex_lock (mutex=0x7f12333da300) at pthread_mutex_lock.c:61
#3  0x0000000000e08036 in rw_pr_rdlock (rwlock=0x7f12333da300) at /home/elenst/bzr/10.0/mysys/thr_rwlock.c:377
#4  0x00000000007913d0 in inline_mysql_prlock_rdlock (that=0x7f12333da300, src_file=0xf2c798 "/home/elenst/bzr/10.0/sql/mdl.cc", src_line=718) at /home/elenst/bzr/10.0/include/mysql/psi/mysql_thread.h:915
#5  0x0000000000791a63 in mdl_iterate_lock (lock=0x7f12333da170, callback=0x7f120d5f55e0 <i_s_metadata_lock_info_fill_row(MDL_ticket*, void*)>, arg=0x7f1238a7c280) at /home/elenst/bzr/10.0/sql/mdl.cc:718
#6  0x0000000000791bd2 in mdl_iterate (callback=0x7f120d5f55e0 <i_s_metadata_lock_info_fill_row(MDL_ticket*, void*)>, arg=0x7f1238a7c280) at /home/elenst/bzr/10.0/sql/mdl.cc:741
#7  0x00007f120d5f5a44 in i_s_metadata_lock_info_fill_table (thd=0x7f1212ae7070, tables=0x7f120cc222e8, cond=0x0) at /home/elenst/bzr/10.0/plugin/metadata_lock_info/metadata_lock_info.cc:127
#8  0x00000000007047c3 in do_fill_table (thd=0x7f1212ae7070, table_list=0x7f120cc222e8, join_table=0x7f120cc569d0) at /home/elenst/bzr/10.0/sql/sql_show.cc:8066
#9  0x0000000000704b3c in get_schema_tables_result (join=0x7f120cc23130, executed_place=PROCESSED_BY_JOIN_EXEC) at /home/elenst/bzr/10.0/sql/sql_show.cc:8164
#10 0x00000000006ac1f1 in JOIN::exec_inner (this=0x7f120cc23130) at /home/elenst/bzr/10.0/sql/sql_select.cc:2520
#11 0x00000000006ab7d0 in JOIN::exec (this=0x7f120cc23130) at /home/elenst/bzr/10.0/sql/sql_select.cc:2355
#12 0x00000000006aeb4f in mysql_select (thd=0x7f1212ae7070, rref_pointer_array=0x7f1212aeb6a0, tables=0x7f120cc222e8, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f120cc23110, unit=0x7f1212aead48, select_lex=0x7f1212aeb428) at /home/elenst/bzr/10.0/sql/sql_select.cc:3292
#13 0x00000000006a527f in handle_select (thd=0x7f1212ae7070, lex=0x7f1212aeac88, result=0x7f120cc23110, setup_tables_done_option=0) at /home/elenst/bzr/10.0/sql/sql_select.cc:372
#14 0x000000000067a251 in execute_sqlcom_select (thd=0x7f1212ae7070, all_tables=0x7f120cc222e8) at /home/elenst/bzr/10.0/sql/sql_parse.cc:5301
#15 0x00000000006725fc in mysql_execute_command (thd=0x7f1212ae7070) at /home/elenst/bzr/10.0/sql/sql_parse.cc:2587
#16 0x000000000067c9db in mysql_parse (thd=0x7f1212ae7070, rawbuf=0x7f120cc22088 "SELECT * FROM INFORMATION_SCHEMA.METADATA_LOCK_INFO", length=51, parser_state=0x7f1238a7d630) at /home/elenst/bzr/10.0/sql/sql_parse.cc:6447
#17 0x000000000066f7a9 in dispatch_command (command=COM_QUERY, thd=0x7f1212ae7070, packet=0x7f1212aed071 "SELECT * FROM INFORMATION_SCHEMA.METADATA_LOCK_INFO", packet_length=51) at /home/elenst/bzr/10.0/sql/sql_parse.cc:1308
#18 0x000000000066eb4b in do_command (thd=0x7f1212ae7070) at /home/elenst/bzr/10.0/sql/sql_parse.cc:1005
#19 0x00000000007880ed in do_handle_one_connection (thd_arg=0x7f1212ae7070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1379
#20 0x0000000000787e40 in handle_one_connection (arg=0x7f1212ae7070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1293
#21 0x0000000000a2cac5 in pfs_spawn_thread (arg=0x7f1212ea30d0) at /home/elenst/bzr/10.0/storage/perfschema/pfs.cc:1853

Stack trace from:

revision-id: sergii@pisem.net-20140228200458-2nzjwfzn554m5aja
revno: 4017
branch-nick: 10.0

RQG grammar (hang.yy):

thread1:
	SELECT * FROM INFORMATION_SCHEMA.TABLES ;

thread2:
	SELECT * FROM INFORMATION_SCHEMA.METADATA_LOCK_INFO ;

RQG command line, assuming the server is already running on port 3306 with metadata_lock_info plugin enabled (either built statically or loaded):

perl ./gentest.pl --dsn="dbi:mysql:port=3306:host=127.0.0.1:user=root:database=test" --duration=600 --queries=100M  --grammar=hang.yy --threads=2

Gliffy Diagrams

Attachments

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Sergey Vojtovich added a comment - 2014-04-23 10:37

Sergei, please review fix for this bug.

Show

Sergey Vojtovich added a comment - 2014-04-23 10:37 Sergei, please review fix for this bug.

Hide

Permalink

Sergei Golubchik added a comment - 2014-05-01 23:06

ok to push

Show

Sergei Golubchik added a comment - 2014-05-01 23:06 ok to push

Hide

Permalink

Sergey Vojtovich added a comment - 2014-05-06 09:44

Fixed in 10.0.11:

revno: 4174
revision-id: svoj@mariadb.org-20140423073406-7o0nrkjwgzfjms7v
parent: psergey@askmonty.org-20140505102454-zwvelnu3jz67cjox
committer: Sergey Vojtovich <svoj@mariadb.org>
branch nick: 10.0-mdev5792
timestamp: Wed 2014-04-23 11:34:06 +0400
message:
  MDEV-5792 - Deadlock between SELECTs from METADATA_LOCK_INFO and another
              I_S table

  mdl_iterate() helper function (which is used by the plugin to iterate mdl
  locks) acquired mutexes in reverse order.

  Fixed by iterating MDL locks in two stages:
  1. Iterate locks hash under the protection of hash mutex, store all
     lock pointers in a thread local array and increment reference counter
     for the lock.
  2. Iterate local array without protection of hash mutex, handle destroyed
     locks.

  It somewhat echoes hack in MDL_map_partition::move_from_hash_to_lock_mutex.

Show

Sergey Vojtovich added a comment - 2014-05-06 09:44 Fixed in 10.0.11: revno: 4174 revision-id: svoj@mariadb.org-20140423073406-7o0nrkjwgzfjms7v parent: psergey@askmonty.org-20140505102454-zwvelnu3jz67cjox committer: Sergey Vojtovich <svoj@mariadb.org> branch nick: 10.0-mdev5792 timestamp: Wed 2014-04-23 11:34:06 +0400 message: MDEV-5792 - Deadlock between SELECTs from METADATA_LOCK_INFO and another I_S table mdl_iterate() helper function (which is used by the plugin to iterate mdl locks) acquired mutexes in reverse order. Fixed by iterating MDL locks in two stages: 1. Iterate locks hash under the protection of hash mutex, store all lock pointers in a thread local array and increment reference counter for the lock. 2. Iterate local array without protection of hash mutex, handle destroyed locks. It somewhat echoes hack in MDL_map_partition::move_from_hash_to_lock_mutex.

People

Assignee:

Sergey Vojtovich

Reporter:

Elena Stepanova

Votes:

0 Vote for this issue

Watchers:

4 Start watching this issue

Dates

Created:

2014-03-05 01:05

Updated:

2014-05-06 09:44

Resolved:

2014-05-06 09:44

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

30m

Agile

View on Board