| Bug #57474 | Deadlock when DDL under LOCK TABLES WRITE, READ + PREPARE. | ||
|---|---|---|---|
| Submitted: | 15 Oct 2010 7:46 | Modified: | 23 Sep 2014 22:20 |
| Reporter: | Dmitry Lenev | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Locking | Severity: | S3 (Non-critical) |
| Version: | 5.5.7-bzr,5.6.2m5 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[15 Oct 2010 8:32]
Valeriy Kravchuk
Verified with current mysql-5.5 from bzr: openxs@ubuntu:~/dbs/5.5/mysql-test$ ./mtr bug57474 Logging: ./mtr bug57474 101015 11:03:17 [Note] Plugin 'FEDERATED' is disabled. MySQL Version 5.5.7 Checking supported features... - skipping ndbcluster, mysqld not compiled with ndbcluster - SSL connections supported - binaries are debug compiled Collecting tests... vardir: /home/openxs/dbs/5.5/mysql-test/var Removing old var directory... Creating var directory '/home/openxs/dbs/5.5/mysql-test/var'... Installing system database... Using server port 52690 ============================================================================== TEST RESULT TIME (ms) ------------------------------------------------------------ worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 worker[1] Trying to dump core for [mysqltest - pid: 2494, winpid: 2494] worker[1] Trying to dump core for [mysqld.1 - pid: 2473, winpid: 2473] main.bug57474 [ fail ] timeout after 900 seconds Test ended at 2010-10-15 11:19:25 Test case timeout after 900 seconds == /home/openxs/dbs/5.5/mysql-test/var/log/bug57474.log == create table t1(i int); create table t2(i int); create table t3(i int); create table t4(i int); lock tables t1 write, t3 read; insert into t3 values ((select count(*) from t4));; rename table t2 to t0, t4 to t2, t0 to t4;; prepare stmt1 from 'select * from t1, t2';; == /home/openxs/dbs/5.5/mysql-test/var/tmp/analyze-timeout-mysqld.1.err == mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/home/openxs/dbs/5.5/mysql-test/var/tmp/mysqld.1.sock' (111) - saving '/home/openxs/dbs/5.5/mysql-test/var/log/main.bug57474/' to '/home/openxs/dbs/5.5/mysql-test/var/log/main.bug57474/' - found 'core' (0/5) Trying 'dbx' to get a backtrace Trying 'gdb' to get a backtrace Core generated by '/home/openxs/dbs/5.5/libexec/mysqld' Output from gdb follows. The first stack trace is from the failing thread. The following stack traces are from all threads (so the failing one is duplicated). -------------------------- [New Thread 2474] [New Thread 2477] [New Thread 2478] [New Thread 2479] [New Thread 2480] [New Thread 2481] [New Thread 2482] [New Thread 2484] [New Thread 2485] [New Thread 2486] [New Thread 2487] [New Thread 2488] [New Thread 2498] [New Thread 2499] [New Thread 2500] [New Thread 2501] warning: Can't read pathname for load map: Input/output error. Core was generated by `/home/openxs/dbs/5.5/libexec/mysqld --defaults-group-suffix=.1 --defaults-file='. Program terminated with signal 6, Aborted. #0 0x00e42422 in __kernel_vsyscall () #0 0x00e42422 in __kernel_vsyscall () #1 0x002f7093 in __pthread_kill (threadid=3079231168, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:64 #2 0x0863a8b9 in my_write_core (sig=6) at stacktrace.c:328 #3 0x0827c074 in handle_segfault (sig=6) at mysqld.cc:2517 #4 <signal handler called> #5 0x00e42422 in __kernel_vsyscall () #6 0x003c4b86 in *__GI___poll (fds=0x45aff4, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:87 #7 0x0827ff0f in handle_connections_sockets () at mysqld.cc:5111 #8 0x0827f405 in mysqld_main (argc=50, argv=0x9dbed98) at mysqld.cc:4581 #9 0x0827874f in main (argc=8, argv=0xbf9119d4) at main.cc:24 Thread 16 (Thread 2501): #0 0x00e42422 in __kernel_vsyscall () #1 0x002f6342 in pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_timedwait.S:179 #2 0x08646e32 in safe_cond_timedwait (cond=0xa36b7bc, mp=0xa36b778, abstime=0xb248736c, file=0x87cf200 "../include/mysql/psi/mysql_thread.h", line=1097) at thr_mutex.c:278 #3 0x084a05dc in inline_mysql_cond_timedwait (that=0xa36b7bc, mutex=0xa36b778, abstime=0xb248736c, src_file=0x87cf367 "mdl.cc", src_line=995) at ../include/mysql/psi/mysql_thread.h:1097 #4 0x084a12f0 in MDL_wait::timed_wait (this=0xa36b778, thd=0xa36b710, abs_timeout=0xb248736c, set_status_on_timeout=true, wait_state_name=0x87cf2f0 "Waiting for table metadata lock") at mdl.cc:995 #5 0x084a2257 in MDL_context::acquire_lock (this=0xa36b778, mdl_request=0xb24873c4, lock_wait_timeout=31536000) at mdl.cc:1796 #6 0x082e06e7 in open_table_get_mdl_lock (thd=0xa36b710, ot_ctx=0xb2487a78, mdl_request=0xb24873c4, flags=512, mdl_ticket=0xb24875f0) at sql_base.cc:2505 #7 0x082e10ab in open_table (thd=0xa36b710, table_list=0xa3a41c8, mem_root=0xb2487a58, ot_ctx=0xb2487a78) at sql_base.cc:2811 #8 0x082e3a04 in open_and_process_table (thd=0xa36b710, lex=0xa3a3230, tables=0xa3a41c8, counter=0xb2487b08, flags=512, prelocking_strategy=0xb2487b0c, has_prelocking_list=false, ot_ctx=0xb2487a78, new_frm_mem=0xb2487a58) at sql_base.cc:4347 #9 0x082e44fb in open_tables (thd=0xa36b710, start=0xb2487b24, counter=0xb2487b08, flags=512, prelocking_strategy=0xb2487b0c) at sql_base.cc:4776 #10 0x082e530c in open_normal_and_derived_tables (thd=0xa36b710, tables=0xa3a3e00, flags=512) at sql_base.cc:5421 #11 0x08338600 in mysql_test_select (stmt=0xa3602a8, tables=0xa3a3e00) at sql_prepare.cc:1474 #12 0x0833945a in check_prepared_statement (stmt=0xa3602a8) at sql_prepare.cc:2004 #13 0x0833bd10 in Prepared_statement::prepare (this=0xa3602a8, packet=0xa3978d8 "select * from t1, t2", packet_len=20) at sql_prepare.cc:3252 #14 0x08339d92 in mysql_sql_stmt_prepare (thd=0xa36b710) at sql_prepare.cc:2367 #15 0x0828d684 in mysql_execute_command (thd=0xa36b710) at sql_parse.cc:2180 #16 0x08296ea5 in mysql_parse (thd=0xa36b710, rawbuf=0xa397818 "prepare stmt1 from 'select * from t1, t2'", length=41, parser_state=0xb2488b08) at sql_parse.cc:5594 #17 0x0828b10f in dispatch_command (command=COM_QUERY, thd=0xa36b710, packet=0xa38e7d1 "prepare stmt1 from 'select * from t1, t2';", packet_length=42) at sql_parse.cc:1139 #18 0x0828a547 in do_command (thd=0xa36b710) at sql_parse.cc:811 #19 0x082887b1 in do_handle_one_connection (thd_arg=0xa36b710) at sql_connect.cc:1192 #20 0x08288611 in handle_one_connection (arg=0xa36b710) at sql_connect.cc:1131 #21 0x086122ac in pfs_spawn_thread (arg=0xa384ff0) at pfs.cc:1015 #22 0x002f196e in start_thread (arg=0xb2489b70) at pthread_create.c:300 #23 0x003d2a4e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130 ... ------------------------------------------------------------ The servers were restarted 0 times Spent 0.000 of 979 seconds executing testcases
[28 Jan 2011 21:07]
Maxim Volkov
I have the exact same issue on 5.5.8.
[14 Mar 2011 22:28]
Roel Van de Paar
Hi Dmitri, This is the closest bug I could find to describe what I am/have been seeing a number of times now: I run a number of threads (let's say 30) with DML(/DLL) going on. Soon, many threads end up in 'Waiting for table metadata lock' state. I grabbed a SHOW PROCESSLIST/SHOW ENGINE INNODB STATUS/SHOW FULL PROCESSLIST/GLOBAL VARS/GLOBAL STATUS output to show what is happening. This seems a rather serious locking failure. Have a look at the output and let me know what you think. The issue is fairly easy to reproduce.
[14 Mar 2011 22:29]
Roel Van de Paar
SHOW PROCESSLIST/SHOW ENGINE INNODB STATUS/SHOW FULL PROCESSLIST/GLOBAL VARS/GLOBAL STATUS
Attachment: out.txt (text/plain), 199.28 KiB.
[14 Mar 2011 22:34]
Roel Van de Paar
(attached) gdb capture of all threads
Attachment: gdb.zip (application/x-zip-compressed, text), 100.88 KiB.
[14 Mar 2011 23:38]
Roel Van de Paar
In the example, the only threads *not* in 'Waiting for table metadata lock' are:
Thread 3 (executing) is using tables t2 t8 t9 t17 t27 t22
Thread 6 (Sending data) is using tables t1 t5 t7 t16 t18 t25 t29
Thread 29 (Sending data) is using tables t1 t7 t3 t10 t18 t21 t23
Yet, for instance thread 13 is 'Waiting for table metadata lock' while the table it is accessing (t6) is not in use by any of the active threads.
Id: 13
Time: 3320
State: Waiting for table metadata lock
Info: insert ignore into `test`.`t6` set `col52` = -1.3764409700144E+18, `col53` = '2011-04-17 04:48:22', `a6` = 0, `col55` = 14038542, `col54` = '2011-10-25 15:35:45'
(There are however other threads attempting to access t6, but those are also in the 'Waiting for table metadata lock' state.)
So, at least for t6 it seems like there is some incorrect (and undetected) deadlock where all relevant threads are in the 'Waiting for table metadata lock' state.
[14 Mar 2011 23:48]
Roel Van de Paar
(There are no foreign keys in the table definitions)
[14 Mar 2011 23:51]
Roel Van de Paar
Could this view (the only one which is referecing both t6 and t5) be the issue? CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `v_4` AS select `t5`.`col43` AS `col43` from (`t6` FORCE INDEX (PRIMARY) FORCE INDEX (`idx25`) FORCE INDEX (`idx28`) left join (`t4` join `t5`) on(isnu ll(`t4`.`col31`))) limit 1;
[15 Mar 2011 0:08]
Roel Van de Paar
(All tables are InnoDB)
[15 Mar 2011 2:18]
Roel Van de Paar
Interestingly, killing some of the active processes, I had a situation where most of those threads all went to 'opening tables', just before most of them reverted to 'Waiting for table metadata lock' again. So, it seems that the lock situation happens *in* or *directly after* the 'opening tables' code.
[15 Mar 2011 6:33]
Dmitry Lenev
Hello Roel! After looking at SHOW PROCESSLIST output and stacktrace that you have provided I think what you observe is a separate bug and not bug #57474. In cases when one encounters bug #57474 there is always at least one connection waiting with status "Waiting for table level lock" and in thr_lock()/wait_for_lock() functions. Since there is no such connection in your case it must be a different issue. Please report a separate bug about your problem!
[18 Oct 2011 15:53]
Fran ois
Hi, I am experiencing a blocking problem after migrating from mysql 5.1 to mysql 5.5 and I think it might be related.
I am randomly blocked running mysql command from commandline generated by mysqldump.
That file contains following lines:
LOCK TABLES `myTable` WRITE;
INSERT INTO `myTable` VALUES ( ...);
UNLOCK TABLES;
The command is sometimes blocked before locking the table and sometimes before inserting the data row (and sometimes not blocked at all).
Is it related? Is there a workaround?
[7 Mar 2012 14:04]
Sveta Smirnova
See bug #64376 also: seems to be duplicate.
[23 Sep 2014 22:20]
Paul DuBois
Changes were made for test suite. No changelog entry needed.
[26 Sep 2014 13:08]
Paul DuBois
Correction; changelog entry is: Execution of DDL statements under LOCK TABLES might have led to deadlock if 1) this LOCK TABLES statement, in addition to the table to be changed by DDL, also had some tables read-locked or locked implicitly (for example, through triggers) and 2) there was some concurrent DML which was blocked on a table-level lock held by LOCK TABLES and 3) there was a concurrent PREPARE (or corresponding connector API call) which prepared a statement using tables to be affected by the first DDL and some other table which was affected by another DDL statement which had to wait for the DML statement.
[26 Sep 2014 13:08]
Paul DuBois
Fixed in 5.7.5.
Description: A deadlock can occur under the following (fairly rare) conditions: - A DDL statement like ALTER or DROP table is executed under LOCK TABLES - This LOCK TABLES statement in addition to table to be changed by DDL also has some tables read-locked or locked implicitly e.g. through triggers. - There is some concurrent DML which is blocked on table-level lock held by LOCK TABLES (i.e. because of the read-lock or implicit lock). This DML also uses some other tables. - There is a concurrent PREPARE (or corresponding C/... API call) which prepares statement using tables to be affected by the first DDL and some other table which is affected by another DDL statement which has to wait for the DML statement. Some parts of this deadlock involve waiting on thr_lock.c locks so they are not visible to deadlock detector of MDL subsystem and it cannot be properly detected by it. How to repeat: # Here is the script for mysqltest tool which allows to reproduce the problem. connect (con1,localhost,root,,test,,); connect (con2,localhost,root,,test,,); connect (con3,localhost,root,,test,,); connection default; create table t1(i int); create table t2(i int); create table t3(i int); create table t4(i int); lock tables t1 write, t3 read; connection con1; --send insert into t3 values ((select count(*) from t4)); connection con2; let $wait_condition= select count(*) = 1 from information_schema.processlist where state = "Waiting for table level lock" and info = "insert into t3 values ((select count(*) from t4))"; --source include/wait_condition.inc --send rename table t2 to t0, t4 to t2, t0 to t4; connection con3; let $wait_condition= select count(*) = 1 from information_schema.processlist where state = "Waiting for table metadata lock" and info = "rename table t2 to t0, t4 to t2, t0 to t4"; --source include/wait_condition.inc --send prepare stmt1 from 'select * from t1, t2'; connection default; let $wait_condition= select count(*) = 1 from information_schema.processlist where state = "Waiting for table metadata lock" and info = "select * from t1, t2"; --source include/wait_condition.inc alter table t1 add column j int;