Bug #68460 blocked with FLUSH TABLES WITH READ LOCK + SHOW SLAVE STATUS
Submitted: 22 Feb 2013 6:37 Modified: 31 May 2013 22:02
Reporter: Queen Aaa Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.10 OS:Linux (CentOS release 5.8 (Final))
Assigned to: CPU Architecture:Any

[22 Feb 2013 6:37] Queen Aaa
Description:
If a client thread on an slave does FLUSH TABLES WITH READ LOCK; 
then master does some updates,
SHOW SLAVE STATUS in the same client will be blocked.

mysql [localhost] {msandbox} ((none)) > show processlist;
+----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+-------------------+
| Id | User        | Host      | db   | Command | Time | State                                                                       | Info              |
+----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+-------------------+
|  1 | system user |           | NULL | Connect |   36 | Slave has read all relay log; waiting for the slave I/O thread to update it | NULL              |
|  2 | system user |           | NULL | Connect |  134 | Waiting for commit lock                                                     | NULL              |
|  3 | system user |           | NULL | Connect |  134 | Waiting for an event from Coordinator                                       | NULL              |
|  4 | system user |           | NULL | Connect |   46 | Waiting for an event from Coordinator                                       | NULL              |
|  5 | msandbox    | localhost | test | Query   |    2 | init                                                                        | show slave status |
|  6 | msandbox    | localhost | NULL | Query   |    0 | init                                                                        | show processlist  |
+----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+-------------------+
6 rows in set (0.00 sec)
id:5

How to repeat:
step 1) setup replication

step 2) in the slave:
mysql [localhost] {msandbox} (test) > flush tables with read lock;
Query OK, 0 rows affected (0.01 sec)

step 3) in the master:
mysql [localhost] {msandbox} (test) > insert into test.t set id=4;
Query OK, 1 row affected (0.01 sec)

step 4) in the SAME session  of step 2:
mysql [localhost] {msandbox} (test) > show slave status;

it will be blocked.

Suggested fix:
don't know.
but it looks it bug 10942.
[22 Feb 2013 9:03] Valeriy Kravchuk
This is easy to repeat with MTR using the following simple test:

[openxs@chief mysql-test]$ cat t/bug68460.test
--source include/master-slave.inc

connection master;
create table t(id int);

--sync_slave_with_master

connection slave;
flush tables with read lock;

connection master;
insert into test.t set id=4;

connection slave;
show slave status;

connection master;
drop table t;

--sync_slave_with_master

This is what one gets when run it:

...
2013-02-22 10:54:20 2665 [Note] Shutting down plugin 'CSV'
MySQL Version 5.6.10
Checking supported features...
 - SSL connections supported
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/5.6/mysql-test/var'...
Installing system database...
Using server port 59406

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.bug68460                            [ fail ]
        Test ended at 2013-02-22 10:59:30

CURRENT_TEST: main.bug68460
=== SHOW MASTER STATUS ===
---- 1. ----
File    slave-bin.000001
Position        216
Binlog_Do_DB
Binlog_Ignore_DB
Executed_Gtid_Set
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State  Waiting for master to send event
Master_Host     127.0.0.1
Master_User     root
Master_Port     13000
Connect_Retry   1
Master_Log_File master-bin.000001
Read_Master_Log_Pos     590
Relay_Log_File  slave-relay-bin.000002
Relay_Log_Pos   380
Relay_Master_Log_File   master-bin.000001
Slave_IO_Running        Yes
Slave_SQL_Running       Yes
Replicate_Do_DB
Replicate_Ignore_DB
Replicate_Do_Table
Replicate_Ignore_Table
Replicate_Wild_Do_Table
Replicate_Wild_Ignore_Table
Last_Errno      0
Last_Error
Skip_Counter    0
Exec_Master_Log_Pos     216
Relay_Log_Space 927
Until_Condition None
Until_Log_File
Until_Log_Pos   0
Master_SSL_Allowed      No
Master_SSL_CA_File
Master_SSL_CA_Path
Master_SSL_Cert
Master_SSL_Cipher
Master_SSL_Key
Seconds_Behind_Master   300
Master_SSL_Verify_Server_Cert   No
Last_IO_Errno   0
Last_IO_Error
Last_SQL_Errno  0
Last_SQL_Error
Replicate_Ignore_Server_Ids
Master_Server_Id        1
Master_UUID     76f0ac4e-7ccd-11e2-ab57-485b3952834f
Master_Info_File        /home/openxs/dbs/5.6/mysql-test/var/mysqld.2/data/master
.info
SQL_Delay       0
SQL_Remaining_Delay
Slave_SQL_Running_State Waiting for global read lock
Master_Retry_Count      10
Master_Bind
Last_IO_Error_Timestamp
Last_SQL_Error_Timestamp
Master_SSL_Crl
Master_SSL_Crlpath
Retrieved_Gtid_Set
Executed_Gtid_Set
Auto_Position   0
=========================

=== SHOW PROCESSLIST ===
---- 1. ----
Id      2
User    root
Host    localhost:49873
db      test
Command Sleep
Time    300
State
Info
---- 2. ----
Id      3
User    root
Host    localhost:49874
db      test
Command Sleep
Time    302
State
Info
---- 3. ----
Id      4
User    system user
Host
db
Command Connect
Time    301
State   Waiting for master to send event
Info
---- 4. ----
Id      5
User    system user
Host
db      test
Command Connect
Time    300
State   Waiting for global read lock
Info    insert into test.t set id=4
---- 5. ----
Id      6
User    root
Host    localhost:49880
db      test
Command Query
Time    0
State   init
Info    SHOW PROCESSLIST
---- 6. ----
Id      7
User    root
Host    localhost:49881
db      test
Command Sleep
Time    300
State
Info
========================

analyze: sync_with_master
mysqltest: At line 20: sync_slave_with_master failed: 'select master_pos_wait('m
aster-bin.000001', 590, 300)' returned -1 indicating timeout after 300 seconds
...
[22 Feb 2013 9:45] MySQL Verification Team
Looks like http://bugs.mysql.com/bug.php?id=67879 fixed in 5.7+ ?
[22 Feb 2013 10:18] Valeriy Kravchuk
Hm, my test case is probably wrong. It hangs upon sync with master because INSERT can not proceed. SHOW SLAVE STATUS does not hand.

Please, send your my.cnf file content from slave.
[22 Feb 2013 11:23] Valeriy Kravchuk
Now, proper test case. From what I see, we have to use tables to store replication info to repeat this. So, here is the test case:

[openxs@chief mysql-test]$ cat t/bug68460.test
--source include/master-slave.inc

connection master;
create database test2;
create table test.t(id int) engine=InnoDB;
create table test2.t(id int) engine=InnoDB;

--sync_slave_with_master

connection slave;
stop slave;
set global slave_parallel_workers=2;
set global master_info_repository='TABLE';
set global sync_master_info=1;
start slave;
flush tables with read lock;

connection master;
insert into test.t set id=4;
insert into test2.t set id=3;

connection slave;
show slave status;
show processlist;

This is how to run it:

./mtr  --mysqld=--relay_log_info_repository=TABLE bug68460

Then just connect to hanging slave and check processlist:

[openxs@chief ~]$ mysql -uroot --host=127.0.0.1 --port=13001
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 12
Server version: 5.6.10-log MySQL Community Server (GPL)

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show processlist;
+----+-------------+-----------------+------+---------+------+---------------------------------------+-------------------+
| Id | User        | Host            | db   | Command | Time | State                                 | Info              |
+----+-------------+-----------------+------+---------+------+---------------------------------------+-------------------+
|  2 | root        | localhost:51048 | test | Sleep   |  322 |                                       | NULL              |
|  3 | root        | localhost:51049 | test | Sleep   |  323 |                                       | NULL              |
|  6 | root        | localhost:51055 | test | Query   |  320 | init                                  | show slave status |
|  7 | root        | localhost:51056 | test | Sleep   |  322 |                                       | NULL              |
|  8 | system user |                 | NULL | Connect |  321 | Waiting for commit lock               | NULL              |
|  9 | system user |                 | NULL | Connect |  321 | Reading event from the relay log      | NULL              |
| 10 | system user |                 | NULL | Connect |  321 | Waiting for an event from Coordinator | NULL              |
| 11 | system user |                 | NULL | Connect |  321 | Waiting for an event from Coordinator | NULL              |
| 12 | root        | localhost:51078 | NULL | Query   |    0 | init                                  | show processlist  |
+----+-------------+-----------------+------+---------+------+---------------------------------------+-------------------+
9 rows in set (0.00 sec)

mtr still hangs...
[22 Feb 2013 12:13] MySQL Verification Team
Hello Queen Aaa,

Thank you for the report.

Verified as described on reported version.

Thanks,
Umesh
[22 Mar 2013 15:35] Mirko Conte
Deadlock can be resolved doing "unlock tables" or closing session, but if a "flush logs" is done after "flush tables with read lock", the mysqld slave server process must be killed.

**When doing a mysqldump with --single-transaction and --flush-logs options and some replication traffic, often the replication threads get locked, the server must be killed and as a result the slave instance misses one GTID after restart.**
[31 May 2013 22:02] Daniel So
Added changelog entry to Reference Manual versions 5.6 and 5.7:

'After the client thread on a slave performed a FLUSH TABLES WITH READ LOCK and was followed by some updates on the master, the slave hung when executing SHOW SLAVE STATUS.'
[18 Jun 2013 19:51] Sveta Smirnova
Bug #69493 was marked as duplicate of this one.
[18 Dec 2013 9:56] Laurynas Biveinis
5.6$ bzr log -r 5158
------------------------------------------------------------
revno: 5158
committer: Sujatha Sivakumar <sujatha.sivakumar@oracle.com>
branch nick: Bug16387720_mysql-5.6
timestamp: Fri 2013-05-24 06:23:14 +0530
message:
  Bug#16387720: BLOCKED WITH FLUSH TABLES WITH READ LOCK + 
  SHOW SLAVE STATUS
  
  Problem:
  =======
  If a client thread on a slave does FLUSH TABLES WITH READ
  LOCK; then master does some updates, SHOW SLAVE STATUS in
  the same client will be blocked. If the blocked slave server
  is killed and restarted when GTID's are enabled, one GTID
  gets missed leaving the slave in an out of sync state.
  
  Using 'relay-log-recovery=1' should do a crash safe slave
  recovery but it is not happening.
  
  Analysis:
  ========
  
  RPL info tables "slave_master_info" and "slave_relay_log_info"
  are used to store slave's thread's positions.  When a FTWRL
  is issued on slave this command blocks all operations on
  tables. Hence when some update operations are done on master
  the slave thread will be able to open the tables but while 
  closing, an internal commit operation will be blocked. These
  blocked info tables make the "SHOW SLAVE STATUS" to hang.
  
  When "relay-log-recovery=1" during crash recovery all the
  partial written events will be discarded the master info
  table is initialised with the information read from relay
  log info table. The "Retrieved GTID" set should be cleared
  so that partial read events are discarded and they are
  fetched once again. Since this is not happening
  "The Retried GTID" is considered to be executed and the 
  actual transaction is skipped.
  
  Fix:
  ===
  
  Info tables should be made independent of global read lock.
  At the time of opening the RPL info tables the following
  "MYSQL_OPEN_IGNORE_GLOBAL_READ_LOCK" flag is set to make
  the info tables not to block when the FTWRL is in progress.
  Hence a similar flag is introduced in "ha_commit_trans"
  code which will allow commit to complete even if a global
  read lock is active. This flag can be used to allow changes
  to internal tables (e.g. slave status tables).
  
  To fix the missing GTID issue using "relay-log-recovery"
  option, during recovery process retrieved GTID set is cleared.
[10 Feb 2014 11:26] James Heggs
Also be advised that the Percona hotbackup tool will issue a 'FLUSH TABLES....' if you do not specify the "--no-lock" option.

Be very careful if you are using a tool, such as nagios to check your slave status whilst taking hot backups.
[14 Apr 2014 21:25] Simon Mudd
Note: this bug is closed but it's not very clear form the reference to the bzr log number at what version this was actually fixed. If possible could you confirm in what versions of MySQL 5.6 this has been resolved?

Thanks.
[14 Apr 2014 21:54] MySQL Verification Team
Fixed in 5.6.13 and 5.7.2

http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-13.html
http://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-2.html

Replication: After the client thread on a slave performed a FLUSH TABLES WITH READ LOCK and was followed by some updates on the master, the slave hung when executing SHOW SLAVE STATUS. (Bug #68460, Bug #16387720)
[11 Sep 2014 10:33] liu hickey
This bug still exists in 5.6.16+, but with different reason.

It's repeatable in single slave sql thread, that is --slave_parallel_workers=0.

The HANG case is:

FTWRL, then SHOW SLAVE STATUS hang, waiting rli->data_lock

worker thread hang, waiting MDL_COMMIT but holding rli->data_lock!

 7431 int Xid_log_event::do_apply_event(Relay_log_info const *rli)
 7442   mysql_mutex_lock(&rli_ptr->data_lock);
 7495   error= do_commit(the);
 7502   mysql_mutex_unlock(&rli_ptr->data_lock);

Obviously, it's a serious bug, as doing backup on SLAVE is so normal.
[11 Sep 2014 10:35] liu hickey
Backtrace:

hread 27 (Thread 0x7f7198240700 (LWP 18877)):
#0  0x00000038f0c0b7cb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x0000000000662250 in MDL_wait::timed_wait(MDL_context_owner*, timespec*, bool, PSI_stage_info_v1 const*) ()
    at /u01/osconn/dev/alisql/include/mysql/psi/mysql_thread.h:1188
#2  0x00000000006640c2 in MDL_context::acquire_lock(MDL_request*, unsigned long) () at /u01/osconn/dev/alisql/sql/mdl.cc:2271
#3  0x00000000005b2fdf in ha_commit_trans(THD*, bool, bool) () at /u01/osconn/dev/alisql/sql/handler.cc:1474
#4  0x000000000078ce09 in trans_commit(THD*) ()
#5  0x000000000089111d in Xid_log_event::do_apply_event(Relay_log_info const*) () at /u01/osconn/dev/alisql/sql/log_event.cc:7344
#6  0x0000000000896bee in Log_event::apply_event(Relay_log_info*) () at /u01/osconn/dev/alisql/sql/log_event.cc:3031
#7  0x00000000008ceed9 in apply_event_and_update_pos(Log_event**, THD*, Relay_log_info*) () at /u01/osconn/dev/alisql/sql/rpl_slave.cc:3502
#8  0x00000000008d1e45 in handle_slave_sql () at /u01/osconn/dev/alisql/sql/rpl_slave.cc:3894
#9  0x0000000000b521c0 in pfs_spawn_thread ()
#10 0x00000038f0c077e1 in start_thread () from /lib64/libpthread.so.0
#11 0x00000038f08e68ed in clone () from /lib64/libc.so.6

Thread 25 (Thread 0x7f71981be700 (LWP 18892)):
#0  0x00000038f0c0e074 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000038f0c0937b in _L_lock_1023 () from /lib64/libpthread.so.0
#2  0x00000038f0c092fe in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000008c40dd in inline_mysql_mutex_lock.constprop.83 () at /u01/osconn/dev/alisql/include/mysql/psi/mysql_thread.h:673
#4  0x00000000008cda84 in show_slave_status(THD*, Master_info*) () at /u01/osconn/dev/alisql/sql/rpl_slave.cc:2683
#5  0x00000000006fa63d in mysql_execute_command(THD*) () at /u01/osconn/dev/alisql/sql/sql_parse.cc:3195
#6  0x00000000006fd498 in mysql_parse(THD*, char*, unsigned int, Parser_state*) () at /u01/osconn/dev/alisql/sql/sql_parse.cc:6729
#7  0x00000000006ff7c0 in dispatch_command(enum_server_command, THD*, char*, unsigned int) () at /u01/osconn/dev/alisql/sql/sql_parse.cc:1634
#8  0x00000000006c391d in do_handle_one_connection(THD*) ()
#9  0x00000000006c3969 in handle_one_connection ()
#10 0x0000000000b521c0 in pfs_spawn_thread ()
#11 0x00000038f0c077e1 in start_thread () from /lib64/libpthread.so.0
#12 0x00000038f08e68ed in clone () from /lib64/libc.so.6
[11 Sep 2014 12:50] Alexey Kopytov
http://bugs.mysql.com/bug.php?id=70307 (currently closed as Won't Fix).
[11 Sep 2014 15:34] liu hickey
With clarified --slave_parallel_workers=0, bug70307 described another hang case, even without client2 in the given test case.
[3 Nov 2014 18:02] monty solomon
We experience the slave hang frequently now -- already twice today. Please fix the problem in 5.6.
[19 Dec 2014 3:04] monty solomon
We experience multiple failures due to this bug every day in version 5.6.

The fix in Oracle bug 19843808 is only for version 5.7.

This bug should be reopened as severity S1 since there is no available workaround for 5.6.

Please backport the fix to version 5.6.

Thanks.
[19 Dec 2014 4:59] Sujatha Sivakumar
Oracle bug 19843808  is fixed in 5.6 as well.  Fix will be available in upcoming 5.6 release