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:
None 
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

[21 Oct 2009 17:32] Matthias Leich
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
[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.