| Bug #48210 | FLUSH TABLES WITH READ LOCK deadlocks against concurrent CREATE PROCEDURE | ||
|---|---|---|---|
| Submitted: | 21 Oct 2009 17:32 | Modified: | 7 Mar 2010 1:42 |
| Reporter: | Matthias Leich | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Locking | Severity: | S3 (Non-critical) |
| Version: | mysql-6.0-codebase-bugfixing | OS: | Any |
| Assigned to: | Jon Olav Hauglid | CPU Architecture: | Any |
| Tags: | locking | ||
[27 Oct 2009 12:24]
Jon Olav Hauglid
To reproduce the deadlock using MTR add these sync points:
=== modified file 'sql/lock.cc'
--- sql/lock.cc 2009-10-12 09:08:34 +0000
+++ sql/lock.cc 2009-10-27 12:03:46 +0000
@@ -265,6 +265,8 @@
&write_lock_used)))
break;
+ DEBUG_SYNC(thd, "grl_check");
+
if (global_read_lock && write_lock_used &&
! (flags & MYSQL_LOCK_IGNORE_GLOBAL_READ_LOCK))
{
=== modified file 'sql/sql_base.cc'
--- sql/sql_base.cc 2009-10-25 13:41:27 +0000
+++ sql/sql_base.cc 2009-10-27 12:04:44 +0000
@@ -935,6 +935,7 @@
bool found= TRUE;
DBUG_ENTER("close_cached_tables");
DBUG_ASSERT(thd || (!wait_for_refresh && !tables));
+ DEBUG_SYNC(thd, "close_cached_tables");
if (!have_lock)
pthread_mutex_lock(&LOCK_open);
The execute the following test case:
--source include/have_debug_sync.inc
connect (con2, localhost, root);
connect (con3, localhost, root);
--echo # Connection 2
connection con2;
SET DEBUG_SYNC= 'grl_check SIGNAL table_opened WAIT_FOR grl_locked';
--send CREATE PROCEDURE p1() SELECT 1
--echo # Now connection 2 has opened mysql.proc
--echo # Connection 1
connection default;
SET DEBUG_SYNC='now WAIT_FOR table_opened';
SET DEBUG_SYNC='close_cached_tables SIGNAL grl_locked WAIT_FOR grl_waiting';
--send FLUSH TABLES WITH READ LOCK
--echo # Now connection 1 has the GRL, about to close cached tables
--echo # Connection 3
connection con3;
--echo # Wait until connection 2 is sleeping, waiting for GRL to go away
--sleep 1
--echo # Then let connection 1 change refresh_version
SET DEBUG_SYNC='now SIGNAL grl_waiting';
--echo # DEADLOCK
[28 Oct 2009 15:46]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/88497 3685 Jon Olav Hauglid 2009-10-28 Bug #48210 FLUSH TABLES WITH READ LOCK deadlocks against concurrent CREATE PROCEDURE This deadlock occured between a) CREATE PROCEDURE (or other commands listed below) b) FLUSH TABLES WITH READ LOCK If the execution of them happened in the following order: - a) opens a table (e.g. mysql.proc) - b) locks the global read lock (or GRL) - a) sleeps inside wait_if_global_read_lock() - b) increases refresh_version and sleeps waiting for old tables to go away Note that a) must start waiting on the GRL before FLUSH increases refresh_version. Otherwise a) won't wait on the GRL and instead close its tables for reopen, allowing FLUSH to complete and thus avoid the deadlock. With this patch the deadlock is avoided by making CREATE PROCEDURE acquire a protection against global read locks before it starts executing. This means that FLUSH TABLES WITH READ LOCK will have to wait until CREATE PROCEDURE completes before acquiring the global read lock, thereby avoiding the deadlock. This is implemented by introducing a new SQL command flag called CF_PROTECT_AGAINST_GRL. Commands marked with this flag will acquire a GRL protection in the beginning of mysql_execute_command(). This patch adds the flag to CREATE, ALTER and DROP for PROCEDURE and FUNCTION, as well as CREATE USER, DROP USER, RENAME USER and REVOKE ALL. All these commands either call open_grant_tables() or open_system_table_for_updated() which make them susceptible for this deadlock. The patch also adds the CF_PROTECT_AGAINST_GRL flag to a number of commands that previously acquired GRL protection in their respective SQLCOM case in mysql_execute_command(). Test case that checks for GRL protection for CREATE PROCEDURE and CREATE USER added to mdl_sync.test.
[29 Oct 2009 7:51]
Jon Olav Hauglid
Pushed to mysql-6.0-codebase-bugfixing (6.0.14-alpha)
[30 Oct 2009 8:01]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/88684 3690 Jon Olav Hauglid 2009-10-30 Postfix for Bug#48210 FLUSH TABLES WITH READ LOCK deadlocks against concurrent CREATE PROCEDURE Rewrote the second test to use DROP PROCEDURE instead of CREATE USER as CREATE USER does not work with embedded server.
[31 Oct 2009 8:20]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091031081410-qkxmjsdzjmj840aq) (version source revid:jon.hauglid@sun.com-20091030080112-uf5pl9qyw8ha5rus) (merge vers: 6.0.14-alpha) (pib:13)
[2 Nov 2009 21:01]
Paul DuBois
Noted in 6.0.14 changelog. FLUSH TABLES WITH READ LOCK could deadlock when executed against concurrent DDL statements for stored routines or account-management statements.
[10 Dec 2009 14:10]
Jon Olav Hauglid
Pushed to mysql-next-4284 (5.6.0-beta).
[16 Feb 2010 16:50]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20091211154405-c9yhiewr9o5d20rq) (merge vers: 6.0.14-alpha) (pib:16)
[16 Feb 2010 16:59]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:kostja@sun.com-20091211103945-198h3pt8w7ypk20u) (pib:16)
[17 Feb 2010 1:17]
Paul DuBois
Setting report to Need Merge pending push of Celosia into release tree.
[6 Mar 2010 10:54]
Bugs System
Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@mysql.com-20100216221947-luyhph0txl2c5tc8) (merge vers: 5.5.99-m3) (pib:16)
[7 Mar 2010 1:42]
Paul DuBois
Noted in 5.5.3 changelog.
[13 Apr 2010 4:59]
Paul DuBois
Correction: Not present in any 5.5.x release. 5.5.3 changelog entry removed.
Description: RQG grammar: ------------ query: CREATE PROCEDURE p1() SELECT 1 | UNLOCK TABLES | FLUSH TABLES WITH READ LOCK; You will see the same problem if you replace the CREATE PROCEDURE ... by CREATE FUNCTION f1 () RETURNS INT RETURN 1 How to execute: --------------- perl runall.pl \ --basedir=<path to your mysql installation> \ --threads=2 --queries=3000 --duration=60 \ --mysqld=--table-lock-wait-timeout=1 \ --mysqld=--innodb-lock-wait-timeout=1 \ --mysqld=--log-output=file \ --reporter=Deadlock,Backtrace,Shutdown \ --gendata=conf/WL5004_data.zz \ --grammar=<see above> \ --seed=872 Result on mysql-6.0-codebase-bugfixing revno: 3654 2009-10-15 + modified ./lib/GenTest/Reporter/Deadlock.pm (RQG) --------------------------------------------------- ... 18:45:03 Executing SHOW PROCESSLIST: $VAR1 = [ [ '1', 'root', 'localhost:52614', 'test', 'Sleep', '31', undef, undef ], [ '6', 'root', 'localhost:52619', 'test', 'Query', '30', 'Waiting for release of readlock', 'CREATE PROCEDURE p1() SELECT 1' ], [ '7', 'root', 'localhost:52620', 'test', 'Query', '30', 'Flushing tables', 'FLUSH TABLES WITH READ LOCK' ], [ '11', 'root', 'localhost:52753', 'test', 'Query', '0', undef, 'SHOW PROCESSLIST' ] ]; .... # ...Killing mysqld with pid 9874 with SIGHUP in order to force debug output. # ...Killing mysqld with pid 9874 with SIGSEGV in order to capture core. ... # Thread 6 (process 9912): #0 0x00007f9c1c8b02e9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0 #1 0x0000000000b98000 in safe_cond_wait (cond=0x1290220, mp=0x128f740, file=0xd0167f "lock.cc", line=1350) at thr_mutex.c:423 #2 0x00000000006eb1cd in wait_if_global_read_lock (thd=0x25b34a8, abort_on_refresh=true, is_not_commit=true) at lock.cc:1350 #3 0x00000000006ecdbb in mysql_lock_tables (thd=0x25b34a8, tables=0x7f9c10060148, count=1, flags=0, need_reopen=0x7f9c1005ffbf) at lock.cc:275 #4 0x0000000000767d59 in open_ltable (thd=0x25b34a8, table_list=0x7f9c10060090, lock_type=TL_WRITE, lock_flags=0) at sql_base.cc:4687 #5 0x0000000000767fe1 in open_system_table_for_update (thd=0x25b34a8, one_table=0x7f9c10060090) at sql_base.cc:8646 #6 0x000000000091300b in open_proc_table_for_update (thd=0x25b34a8) at sp.cc:270 #7 0x00000000009137f2 in sp_create_routine (thd=0x25b34a8, type=2, sp=0x2580800) at sp.cc:758 #8 0x000000000090b683 in sp_head::create (this=0x2580800, thd=0x25b34a8) at sp_head.cc:731 #9 0x0000000000710a6c in mysql_execute_command (thd=0x25b34a8) at sql_parse.cc:4274 #10 0x0000000000712b87 in mysql_parse (thd=0x25b34a8, inBuf=0x25d91a0 "CREATE PROCEDURE p1() SELECT 1", length=30, found_semicolon=0x7f9c10062900) at sql_parse.cc:5991 #11 0x00000000007137d2 in dispatch_command (command=COM_QUERY, thd=0x25b34a8, packet=0x25c1439 "CREATE PROCEDURE p1() SELECT 1", packet_length=30) at sql_parse.cc:1074 #12 0x0000000000714d3d in do_command (thd=0x25b34a8) at sql_parse.cc:756 #13 0x0000000000701784 in handle_one_connection (arg=0x25b34a8) at sql_connect.cc:1164 #14 0x00007f9c1c8ac3ba in start_thread () from /lib/libpthread.so.0 #15 0x00007f9c1b818fcd in clone () from /lib/libc.so.6 #16 0x0000000000000000 in ?? () ... # 18:45:28 Thread 7 (process 9914): # 18:45:28 #0 0x00007f9c1c8b02e9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0 # 18:45:28 #1 0x0000000000b98000 in safe_cond_wait (cond=0x12901a0, mp=0x128f4c0, file=0xd6888c "sql_base.cc", line=1059) at thr_mutex.c:423 # 18:45:28 #2 0x0000000000769874 in close_cached_tables (thd=0x25cd1f8, tables=0x0, have_lock=false, wait_for_refresh=true) at sql_base.cc:1059 # 18:45:28 #3 0x00000000007044bd in reload_acl_and_cache (thd=0x25cd1f8, options=16388, tables=0x0, write_to_binlog=0x7f9c10020360) at sql_parse.cc:6937 # 18:45:28 #4 0x000000000071006f in mysql_execute_command (thd=0x25cd1f8) at sql_parse.cc:4095 # 18:45:28 #5 0x0000000000712b87 in mysql_parse (thd=0x25cd1f8, inBuf=0x221d760 "FLUSH TABLES WITH READ LOCK", length=27, found_semicolon=0x7f9c10021900) at sql_parse.cc:5991 # 18:45:28 #6 0x00000000007137d2 in dispatch_command (command=COM_QUERY, thd=0x25cd1f8, packet=0x1890ab9 "FLUSH TABLES WITH READ LOCK", packet_length=27) at sql_parse.cc:1074 # 18:45:28 #7 0x0000000000714d3d in do_command (thd=0x25cd1f8) at sql_parse.cc:756 # 18:45:28 #8 0x0000000000701784 in handle_one_connection (arg=0x25cd1f8) at sql_connect.cc:1164 # 18:45:28 #9 0x00007f9c1c8ac3ba in start_thread () from /lib/libpthread.so.0 # 18:45:28 #10 0x00007f9c1b818fcd in clone () from /lib/libc.so.6 # 18:45:28 #11 0x0000000000000000 in ?? () ... A parallel look via mysql shows mysql> SHOW PROCESSLIST; (output is edited) +--+-------+----+-------------------------------+------------------------------ |Id|Command|Time|State |Info +--+-------+----+-------------------------------+------------------------------+ | 1|Sleep | 11|NULL |NULL | 6|Query | 10|Waiting for release of readlock|CREATE PROCEDURE p1() SELECT 1 | 7|Query | 10|Flushing tables |FLUSH TABLES WITH READ LOCK | 9|Query | 0|NULL |SHOW PROCESSLIST | +------------------------------------------------ My environment: - mysql compiled with compile-pentium64-debug-max - Linux OpenSuSE 11.0 (64 Bit) - Intel Core2Duo mysql-5.1-bugteam revno: 3146 2009-10-06 does not show this deadlock. How to repeat: See above