MySQL Bugs: #69493: Slave deadlock by show slave status, global read lock and slave_master

Bug #69493	Slave deadlock by show slave status, global read lock and slave_master_info
Submitted:	17 Jun 2013 17:53	Modified:	18 Jun 2013 19:50
Reporter:	Yoshinori Matsunobu (OCA)	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	Tests: Replication	Severity:	S7 (Test Cases)
Version:	5.6.12	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
This is similar to #67879, but is different:
- Repeats in "5.6, master_info_repository=TABLE" only
- Repeats even without STOP SLAVE

So this is more serious for users who use 5.6 and master_info_repository=TABLE.

How to repeat:
Run master and slave. Set sync_master_info=1 (or small enough value) and master_info_repository=table on slave.

master)
 CREATE TABLE `t1` (
   `id` int(11) NOT NULL,
   `value` int(11) DEFAULT NULL,
   `value2` text,
   PRIMARY KEY (`id`)
 ) ENGINE=InnoDB DEFAULT CHARSET=latin1 

slave)
 FLUSH TABLES WITH READ LOCK;

master)
 INSERT INTO t1 VALUES (1,1,1);

slave)
 SHOW SLAVE STATUS; => hangup

SQL thread waited at "Waiting for global read lock". Global read lock was held by FLUSH TABLES WITH READ LOCK.

I/O thread waited at "Waiting for commit lock". I/O thread tried to update (and commit) slave_master_info table, but it was blocked by FLUSH TABLES WITH READ LOCK.

SQL thread was blocked at "mysql_mutex_lock(&mi->data_lock)". data_lock was held by I/O thread as below.
--
      mysql_mutex_lock(&mi->data_lock);
      if (flush_master_info(mi, FALSE))
      {
        mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR,
                   ER(ER_SLAVE_FATAL_ERROR),
                   "Failed to flush master info.");
        mysql_mutex_unlock(&mi->data_lock);
        goto err;
      }
      mysql_mutex_unlock(&mi->data_lock);
--

I/O thread stack:
Thread 4 (Thread 0x40a21940 (LWP 21601)):
#0  0x0000003ea4c0b150 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006608dc in inline_mysql_cond_timedwait (src_line=<optimized out>, src_file=<optimized out>, abstime=<optimized out>, mutex=<optimized out>, that=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/include/mysql/psi/mysql_thread.h:1199
#2  MDL_wait::timed_wait (this=0x1a5b738, owner=0x1a5b650, abs_timeout=0x40a209e0, set_status_on_timeout=true, wait_state_name=0x1228128) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/mdl.cc:1305
#3  0x0000000000662295 in MDL_context::acquire_lock (this=0x1a5b738, mdl_request=0x40a20a50, lock_wait_timeout=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/mdl.cc:2241
#4  0x000000000058ca9e in ha_commit_trans (thd=0x1a5b650, all=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/handler.cc:1396
#5  0x00000000008e1c1c in Rpl_info_table_access::close_table (this=0x144c6a0, thd=0x1a5b650, table=0x1, backup=0x40a20d60, error=20) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_info_table_access.cc:158
#6  0x00000000008e1149 in Rpl_info_table::do_flush_info (this=0x1919f40, force=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_info_table.cc:238
#7  0x00000000008d32ea in flush_info (force=<optimized out>, this=0x1a5b774) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_info_handler.h:92
#8  Master_info::flush_info (this=0x18ed650, force=false) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_mi.cc:275
#9  0x00000000008c24fe in flush_master_info (mi=0x18ed650, force=false) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:617
#10 0x00000000008d1c7e in handle_slave_io (arg=0x18ed650) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:4265

SQL Thread stack:
Thread 3 (Thread 0x41aa2940 (LWP 21603)):
#0  0x0000003ea4c0b150 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006608dc in inline_mysql_cond_timedwait (src_line=<optimized out>, src_file=<optimized out>, abstime=<optimized out>, mutex=<optimized out>, that=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/include/mysql/psi/mysql_thread.h:1199
#2  MDL_wait::timed_wait (this=0x1a6cda8, owner=0x1a6ccc0, abs_timeout=0x41a9f9f0, set_status_on_timeout=true, wait_state_name=0x1228080) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/mdl.cc:1305
#3  0x0000000000662295 in MDL_context::acquire_lock (this=0x1a6cda8, mdl_request=0x41a9fad0, lock_wait_timeout=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/mdl.cc:2241
#4  0x00000000006a2c98 in open_table (thd=0x1a6ccc0, table_list=0x1a74390, ot_ctx=0x41a9fdd0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_base.cc:2775
#5  0x00000000006a6251 in open_and_process_table (ot_ctx=<optimized out>, has_prelocking_list=<optimized out>, prelocking_strategy=<optimized out>, flags=<optimized out>, counter=<optimized out>, tables=<optimized out>, lex=0x1a6ed98, thd=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_base.cc:4516
#6  open_tables (thd=0x1a6ccc0, start=0x41a9fe78, counter=0x1a6ee40, flags=0, prelocking_strategy=0x41a9fe90) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_base.cc:4951
#7  0x00000000006a63f7 in open_normal_and_derived_tables (thd=0x1a6cde4, tables=0x1a74390, flags=4294967295) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_base.cc:5638
#8  0x00000000006d4437 in mysql_insert (thd=0x1a6ccc0, table_list=0x1a74390, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_insert.cc:702
#9  0x00000000006ea7ca in mysql_execute_command (thd=0x1a6ccc0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_parse.cc:3396
#10 0x00000000006ee718 in mysql_parse (thd=0x1a6ccc0, rawbuf=0x1968b39 "insert into t1 values (10, 10, 10)", length=<optimized out>, parser_state=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/sql_parse.cc:6187
#11 0x0000000000892f6b in Query_log_event::do_apply_event (this=0x19e8d50, rli=0x19457d0, query_arg=0x1968b39 "insert into t1 values (10, 10, 10)", q_len_arg=34) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/log_event.cc:4735
#12 0x000000000088a30d in Log_event::apply_event (this=0x19e8d50, rli=0x19457d0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/log_event.cc:2970
#13 0x00000000008cd99b in apply_event_and_update_pos (ptr_ev=0x41aa1818, thd=0x1a6ccc0, rli=0x19457d0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:3374
#14 0x00000000008ce4c8 in exec_relay_log_event (thd=0x1a6ccc0, rli=0x19457d0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:3742
#15 0x00000000008cf7e9 in handle_slave_sql (arg=<optimized out>) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:5552

SHOW SLAVE STATUS stack:
Thread 5 (Thread 0x409e0940 (LWP 21589)):
#0  0x0000003ea4c0d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x0000003ea4c08e50 in _L_lock_1233 () from /lib64/libpthread.so.0
#2  0x0000003ea4c08dd3 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000008c782d in inline_mysql_mutex_lock (src_line=<optimized out>, src_file=<optimized out>, that=0x18edab0) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/include/mysql/psi/mysql_thread.h:688
#4  show_slave_status (thd=0x1a53490, mi=0x18ed650) at /export/home/pb2/build/sb_0-9307864-1369154818.19/mysql-5.6.12/sql/rpl_slave.cc:2610

'SQL thread was blocked at "mysql_mutex_lock(&mi->data_lock)"'

=> 'SHOW SLAVE STATUS was blocked at "mysql_mutex_lock(&mi->data_lock)"'

Reminds me of: http://bugs.mysql.com/bug.php?id=68460
It is fixed already, we should wait for next release to test it..

Thanks Shane. I didn't notice Bug#68460. Sorry for submitting a duplicate bug report.

Thank you for the feedback.

Closed as duplicate of Bug#68460.