SHOW SLAVE STATUS hangs

[monty solomon]

mysql> show processlist;
+------+----------------+-----------------+-------+---------+--------+----------------------------------------+-------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+------+----------------+-----------------+-------+---------+--------+----------------------------------------+-------------------+-----------+---------------+
| 42 | SUSR_Heartbeat | 127.0.0.1:45020 | NULL | Query | 123719 | init | show slave status | 0 | 0 |
| 46 | system user | | NULL | Connect | 131101 | Queueing master event to the relay log | NULL | 0 | 0 |
| 47 | system user | | NULL | Connect | 131675 | Waiting for commit lock | NULL | 0 | 0 |
| 332 | root | localhost | NULL | Query | 123742 | init | SHOW SLAVE STATUS | 0 | 0 |
| 334 | SUSR_Heartbeat | 127.0.0.1:46323 | NULL | Query | 123539 | init | show slave status | 0 | 0 |
| 335 | SUSR_Heartbeat | 127.0.0.1:46324 | NULL | Query | 123599 | init | show slave status | 0 | 0 |
| 336 | SUSR_Heartbeat | 127.0.0.1:46325 | NULL | Query | 123659 | init | show slave status | 0 | 0 |
| 340 | SUSR_Heartbeat | 127.0.0.1:46335 | NULL | Query | 123359 | init | show slave status | 0 | 0 |
| 341 | SUSR_Heartbeat | 127.0.0.1:46336 | NULL | Query | 123479 | init | show slave status | 0 | 0 |
| 342 | SUSR_Heartbeat | 127.0.0.1:46337 | NULL | Query | 123419 | init | show slave status | 0 | 0 |
| 346 | SUSR_Heartbeat | 127.0.0.1:46348 | NULL | Query | 123299 | init | show slave status | 0 | 0 |
| 347 | SUSR_Heartbeat | 127.0.0.1:46349 | NULL | Query | 123239 | init | show slave status | 0 | 0 |
| 348 | SUSR_Heartbeat | 127.0.0.1:46350 | NULL | Query | 123179 | init | show slave status | 0 | 0 |
| 352 | SUSR_Heartbeat | 127.0.0.1:46362 | NULL | Query | 122999 | init | show slave status | 0 | 0 |
| 353 | SUSR_Heartbeat | 127.0.0.1:46363 | NULL | Query | 123119 | init | show slave status | 0 | 0 |
| 354 | SUSR_Heartbeat | 127.0.0.1:46364 | NULL | Query | 123059 | init | show slave status | 0 | 0 |
| 358 | SUSR_Heartbeat | 127.0.0.1:46374 | NULL | Query | 122938 | init | show slave status | 0 | 0 |
| 359 | SUSR_Heartbeat | 127.0.0.1:46375 | NULL | Query | 122878 | init | show slave status | 0 | 0 |
| 518 | root | localhost | NULL | Query | 116575 | init | SHOW SLAVE STATUS | 0 | 0 |
| 675 | root | localhost | NULL | Query | 108307 | init | SHOW SLAVE STATUS | 0 | 0 |
| 832 | root | localhost | NULL | Query | 101946 | init | SHOW SLAVE STATUS | 0 | 0 |
| 989 | root | localhost | NULL | Query | 93683 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1146 | root | localhost | NULL | Query | 86599 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1303 | root | localhost | NULL | Query | 79176 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1460 | root | localhost | NULL | Query | 72558 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1617 | root | localhost | NULL | Query | 64801 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1774 | root | localhost | NULL | Query | 58595 | init | SHOW SLAVE STATUS | 0 | 0 |
| 1931 | root | localhost | NULL | Query | 50480 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2012 | root | localhost | mysql | Query | 48241 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2091 | root | localhost | NULL | Query | 43341 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2248 | root | localhost | NULL | Query | 37136 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2405 | root | localhost | NULL | Query | 28899 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2562 | root | localhost | NULL | Query | 22128 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2758 | root | localhost | NULL | Query | 14131 | init | SHOW SLAVE STATUS | 0 | 0 |
| 2876 | root | localhost | NULL | Query | 7733 | init | SHOW SLAVE STATUS | 0 | 0 |
| 3033 | root | localhost | NULL | Query | 1139 | init | SHOW SLAVE STATUS | 0 | 0 |
| 3035 | root | localhost | NULL | Query | 0 | init | show processlist | 0 | 0 |
+------+----------------+-----------------+-------+---------+--------+----------------------------------------+-------------------+-----------+---------------+
37 rows in set (0.00 sec)

[monty solomon (monty+launchpad)]

mysql Ver 14.14 Distrib 5.6.21-69.0, for Linux (x86_64) using EditLine wrapper
Server version: 5.6.21-69.0-log Percona Server (GPL), Release 69.0, Revision 675

Linux tonopah 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
CentOS release 6.5 (Final)

[monty solomon (monty+launchpad)]

SHOW SLAVE STATUS is hung on another slave running a different version -- 5.6.20.

mysql Ver 14.14 Distrib 5.6.20-68.0, for Linux (x86_64) using EditLine wrapper
Server version: 5.6.20-68.0-log Percona Server (GPL), Release 68.0, Revision 656

mysql> show processlist;
+------+----------------+---------------------+-------+---------+--------+----------------------------------------+-------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+------+----------------+---------------------+-------+---------+--------+----------------------------------------+-------------------------------+-----------+---------------+
| 41 | SUSR_Heartbeat | 127.0.0.1:57331 | NULL | Query | 114854 | init | show slave status | 0 | 0 |
| 48 | system user | | NULL | Connect | 130684 | Queueing master event to the relay log | NULL | 0 | 0 |
| 49 | system user | | NULL | Connect | 193633 | Waiting for commit lock | NULL | 0 | 0 |
| 796 | root | localhost | NULL | Query | 114894 | init | SHOW SLAVE STATUS | 0 | 0 |
| 797 | SUSR_Monitor | 10.205.50.214:48181 | NULL | Query | 114876 | init | SHOW SLAVE STATUS | 0 | 0 |
| 799 | SUSR_Heartbeat | 127.0.0.1:60307 | NULL | Query | 114794 | init | show slave status | 0 | 0 |
| 800 | SUSR_Heartbeat | 127.0.0.1:60308 | NULL | Query | 114674 | init | show slave status | 0 | 0 |
| 801 | SUSR_Heartbeat | 127.0.0.1:60309 | NULL | Query | 114734 | init | show slave status | 0 | 0 |
| 845 | SUSR_Heartbeat | 127.0.0.1:60481 | NULL | Query | 114614 | init | show slave status | 0 | 0 |
| 846 | SUSR_Heartbeat | 127.0.0.1:60482 | NULL | Query | 114494 | init | show slave status | 0 | 0 |
| 847 | SUSR_Heartbeat | 127.0.0.1:60483 | NULL | Query | 114554 | init | show slave status | 0 | 0 |
| 851 | SUSR_Heartbeat | 127.0.0.1:60492 | NULL | Query | 114434 | init | show slave status | 0 | 0 |
| 852 | SUSR_Heartbeat | 127.0.0.1:60494 | NULL | Query | 114374 | init | show slave status | 0 | 0 |
| 853 | SUSR_Heartbeat | 127.0.0.1:60495 | NULL | Query | 114314 | init ...

[monty solomon (monty+launchpad)]

I have seen this problem occur on multiple slaves (same or different masters).

This bug may be related to upstream 68460, 67879, and/or 70307.

http://bugs.mysql.com/bug.php?id=68460

http://bugs.mysql.com/bug.php?id=67879

http://bugs.mysql.com/bug.php?id=70307

[Valerii Kravchuk (valerii-kravchuk)]

Can you, please, share my.cnf file content from one of these affected slaves? Any ideas of a sequence of events (other than FLUSH TABLES WITH READ LOCK call) that cause these hangs?

[monty solomon (monty+launchpad)]

The servers are running on AWS instances using EBS volumes for the data and logs volumes.

ec2-consistent-snapshot is periodically used to create a consistent snapshot of the databases and filesystems.

pt-heartbeat and other monitoring software runs periodically.

[monty solomon (monty+launchpad)]

Using show slave status nolock did not prevent the problem in Percona 5.6.21.

mysql Ver 14.14 Distrib 5.6.21-69.0, for Linux (x86_64) using EditLine wrapper
Server version: 5.6.21-69.0-log Percona Server (GPL), Release 69.0, Revision 675

mysql> show processlist;
+-----+----------------+-----------------+------+---------+------+----------------------------------------+--------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+-----+----------------+-----------------+------+---------+------+----------------------------------------+--------------------------+-----------+---------------+
| 7 | SUSR_Heartbeat | 127.0.0.1:41354 | NULL | Query | 3920 | init | show slave status nolock | 0 | 0 |
| 92 | system user | | NULL | Connect | 9127 | Queueing master event to the relay log | NULL | 0 | 0 |
| 93 | system user | | NULL | Connect | 3990 | Waiting for commit lock | NULL | 0 | 0 |
| 427 | root | localhost | NULL | Query | 3946 | init | SHOW SLAVE STATUS NOLOCK | 0 | 0 |
| 429 | SUSR_Heartbeat | 127.0.0.1:42906 | NULL | Query | 3860 | init | show slave status nolock | 0 | 0 |
| 430 | SUSR_Heartbeat | 127.0.0.1:42907 | NULL | Query | 3260 | init | show slave status nolock | 0 | 0 |
| 431 | SUSR_Heartbeat | 127.0.0.1:42908 | NULL | Query | 3320 | init | show slave status nolock | 0 | 0 |
| 432 | SUSR_Heartbeat | 127.0.0.1:42909 | NULL | Query | 3380 | init | show slave status nolock | 0 | 0 |
| 433 | SUSR_Heartbeat | 127.0.0.1:42910 | NULL | Query | 3440 | init | show slave status nolock | 0 | 0 |
| 434 | SUSR_Heartbeat | 127.0.0.1:42911 | NULL | Query | 3500 | init | show slave status nolock | 0 | 0 |
| 435 | SUSR_Heartbeat | 127.0.0.1:42912 | NULL | Query | 3560 | init | show slave status nolock | 0 | 0 |
| 436 | SUSR_Heartbeat | 127.0.0.1:42913 | NULL | Query | 3620 | init | show slave status nolock | 0 | 0 |
| 437 | SUSR_Heartbeat | 127.0.0.1:42914 | NULL | Query | 3680 | init | show slave status nolock | 0 | 0 |
| 438 | SUSR_Heartbeat | 127.0.0.1:42915 | NULL | Query | 3800 | init | show slave status nolock | 0 | 0 |
| 439 | SUSR_Heartbeat | 127.0.0.1:42916 | NULL | Query | 3740 | init | show slave status nolock | 0 | 0 ...

[Valerii Kravchuk (valerii-kravchuk)]

Main question is:

Do you execute FLUSH TABLES WITH READ LOCK before/when getting into this state?

If you do, then upstream bug http://bugs.mysql.com/bug.php?id=68460 and/or http://bugs.mysql.com/bug.php?id=70307 is the reason.

[monty solomon (monty+launchpad)]

The problems in both of those upstream bugs is caused by using SHOW SLAVE STATUS.

I was using the Percona lock-free version of SHOW SLAVE STATUS to prevent the problem but it didn't.

Is the Percona lock-free version of SHOW SLAVE STATUS still using a lock?

[Nilnandan Joshi (nilnandan-joshi)]

Able to reproduce the same with PS 5.6.21, with the testcase http://bugs.mysql.com/file.php?id=20542&bug_id=70307

On Master:

mysql> CREATE TABLE `test`.`keyvalue` (
    -> `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
    -> `name` varchar(40),
    -> PRIMARY KEY (`id`)
    -> ) ENGINE=Innodb;
Query OK, 0 rows affected (0.04 sec)

mysql> set @id:=0;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into `keyvalue` values (@id:=@id+1,md5(rand()*5000000)),(@id:=@id+1,md5(rand()*5000000)),(@id:=@id+1,md5(rand()*5000000)),(@id:=@id+1,md5(rand()*5000000));
Query OK, 4 rows affected, 1 warning (0.01 sec)
Records: 4 Duplicates: 0 Warnings: 1

On Slave:

mysql> flush tables with read lock;
Query OK, 0 rows affected (35.82 sec)

On Master:

mysql> insert into `keyvalue`(`id`,`name`) select @id:=@id+1,md5(rand()*5000000) from `keyvalue` k1, `keyvalue` k2, `keyvalue` k3, `keyvalue` k4,`keyvalue` k5,`keyvalue` k6, `keyvalue` k7, `keyvalue` k8, `keyvalue` k9,`keyvalue` k0,`keyvalue` ka, `keyvalue` kb, `keyvalue` kc, `keyvalue` kd limit 5000000;
Query OK, 5000000 rows affected, 3 warnings (43.59 sec)
Records: 5000000 Duplicates: 0 Warnings: 3

On Slave: session 1

mysql> show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
| 1 | system user | | NULL | Connect | 380 | Waiting for master to send event | NULL | 0 | 0 |
| 2 | system user | | NULL | Connect | 144 | Waiting for commit lock | NULL | 0 | 0 |
| 3 | root | localhost | NULL | Query | 0 | init | show processlist | 0 | 0 |
| 4 | root | localhost | NULL | Sleep | 166 | | NULL | 0 | 0 |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
4 rows in set (0.00 sec)

mysql>
mysql> show slave status \G

Hang........

On Slave: session 2 and 3

mysql> show slave status \G

Hang

Even with NONBLOCKING

On Slave: session 4

mysql> show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+-------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+-------------+-----------+------+---------+------+----------------------------------+-------------------------------+-----------+---------------+
| 1 | system user | | NULL | Connect | 919 | Waiting for master to send event | NULL | 0 | 0 |
| 2 | system user | | NULL | Connect | 683 | Waiting...

[Laurynas Biveinis (laurynas-biveinis)]

Nilnandan -

Which upstream bug does the testcase refer to?

Monty -

The NOLOCK version of SHOW SLAVE STATUS prevents taking of Master_info::run_lock, but not of other locks. MI::run_lock is not one of the deadlocking locks in http://bugs.mysql.com/bug.php?id=70307.

[Nilnandan Joshi (nilnandan-joshi)]

Laurynas,

http://bugs.mysql.com/bug.php?id=70307 (please check [12 Sep 2013 19:40] Umesh Umesh)
http://bugs.mysql.com/file.php?id=20542&bug_id=70307

[Laurynas Biveinis (laurynas-biveinis)]

Thanks Nil, I see this bug was confirmed as upstream 70307. In order to fully confirm 70307, we'd need to see the stacktraces of deadlocked threads in original reporter's setup. We can either do that, either just assume it's 70307.

Monty, can attach with GDB once the issue happens to take the stacktraces or is making this a copy of 70307 good enough for you?

[monty solomon (monty+launchpad)]

Attaching backtrace

mysql> show processlist;
+------+----------------+-----------------+------+---------+--------+----------------------------------------+--------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+------+----------------+-----------------+------+---------+--------+----------------------------------------+--------------------------+-----------+---------------+
| 15 | SUSR_Heartbeat | 127.0.0.1:37051 | NULL | Query | 7463 | init | show slave status nolock | 0 | 0 |
| 17 | system user | | NULL | Connect | 187071 | Queueing master event to the relay log | NULL | 0 | 0 |
| 18 | system user | | NULL | Connect | 7495 | Waiting for commit lock | NULL | 0 | 0 |
| 7179 | root | localhost | NULL | Query | 7495 | init | SHOW SLAVE STATUS | 0 | 0 |
| 7181 | SUSR_Heartbeat | 127.0.0.1:40883 | NULL | Query | 7403 | init | show slave status nolock | 0 | 0 |
| 7182 | SUSR_Heartbeat | 127.0.0.1:40884 | NULL | Query | 7283 | init | show slave status nolock | 0 | 0 |
| 7183 | SUSR_Heartbeat | 127.0.0.1:40885 | NULL | Query | 7343 | init | show slave status nolock | 0 | 0 |
| 7184 | SUSR_Heartbeat | 127.0.0.1:40886 | NULL | Query | 7223 | init | show slave status nolock | 0 | 0 |
| 7189 | SUSR_Heartbeat | 127.0.0.1:40900 | NULL | Query | 6983 | init | show slave status nolock | 0 | 0 |
| 7190 | SUSR_Heartbeat | 127.0.0.1:40901 | NULL | Query | 7163 | init | show slave status nolock | 0 | 0 |
| 7191 | SUSR_Heartbeat | 127.0.0.1:40902 | NULL | Query | 7043 | init | show slave status nolock | 0 | 0 |
| 7192 | SUSR_Heartbeat | 127.0.0.1:40903 | NULL | Query | 7103 | init | show slave status nolock | 0 | 0 |
| 7197 | SUSR_Heartbeat | 127.0.0.1:40916 | NULL | Query | 6683 | init | show slave status nolock | 0 | 0 |
| 7198 | SUSR_Heartbeat | 127.0.0.1:40917 | NULL | Query | 6923 | init | show slave status nolock | 0 | 0 |
| 7199 | SUSR_Heartbeat | 127.0.0.1:40918 | NULL | Query | 6743 | init | show slave status nolock | 0 | 0 |
| 7200 | SUSR_Heartbeat | 127.0.0.1:40919 | NULL | Query | 6863 | init | show slave status nolock | 0 | 0 |
...

[Nilnandan Joshi (nilnandan-joshi)]

I think, its confirmed and we assume that, it is #70307. Laurynas, please let us know if you need anything from us. Thanks.

[Laurynas Biveinis (laurynas-biveinis)]

Threads 6-9, 11-21 "show slave status nolock" waits for mi->data_lock
Thread 10 "show slave status" waits for rli->data_lock, has mi->data_lock
Thread 5 slave I/O thread waits for waits for mi->data_lock
Thread 4 slave SQL thread waits for MDL commit lock, has rli->data_lock
Thread 3 "show slave status" waits for LOCK_active_mi

Something must have the FTWRL or a similar lock that prevents commit.

Thread 4 corresponds to Thread 27 of 70307 two-thread deadlock stacktrace, and Thread 10 corresponds to other one.

Confirmed upstream 70307.

[monty solomon (monty+launchpad)]

xtrabackup sometimes fails.

innobackupex-1.5.1: Error: Connection to mysql child process (pid=15363) timedout. (Time limit of 900 seconds exceeded. You may adjust time limit by editing the value of parameter "$mysql_response_timeout" in this script.) while waiting for reply to MySQL request: 'SHOW SLAVE STATUS\G' at /usr/bin/innobackupex-1.5.1 line 386.
Value of status is : 0
Something happened to the backup, send email

[Peiran Song (peiran-song)]

A customer i48644 encountered the same problem on PS 5.6.19 during xtrabackup run. When he turned off the new binlog lock feature, the slave sql thread was observed "Waiting for commit lock" and SHOW SLAVE STATUS was blocked. But I didn't reproduce it on PS 5.6.19. In all my tests, FTWRL caused slave sql thread to wait on "Waiting for global read lock" which didn't block SHOW SLAVE STATUS.

[monty solomon (monty+launchpad)]

The problem occurs almost every day on one or more servers. Last night it happened on several servers that are running 5.6..21-70.

It appears that enabling multi-threaded replication (MTR) on the slave may use code paths that avoid the bug and be a workaround. I am testing to see if the problem recurs on a slave running MTR.

[monty solomon (monty+launchpad)]

Enabling multi-threaded replication (MTR) on the slave does not prevent the issue.

[monty solomon (monty+launchpad)]

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.

Please fix in version 5.6.

Thanks.

[monty solomon (monty+launchpad)]

Upstream reports that Oracle bug 19843808 is fixed in 5.6 and will be available in an upcoming release.

[monty solomon (monty+launchpad)]

Oracle bug 19843808 is fixed in 5.6.23.

http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-23.html

Replication: If a client thread on a slave executed FLUSH TABLES WITH READ LOCK while the master executed a DML, executing SHOW SLAVE STATUS in the same client became blocked, causing a deadlock. The fix ensures that the read lock is only held during the period that the relay log is being updated and the deadlock is avoided. (Bug #19843808)

[monty solomon (monty+launchpad)]

FYI, the NONBLOCKING option was removed in 5.7.6.

Excerpt from

http://dev.mysql.com/doc/refman/5.7/en/show-slave-status.html
This option was removed in MySQL 5.7.6 due to locking changes that render it unnecessary.

The upstream fix for bug 19843808 in 5.6.23 may eliminate the need for a nolock or nonblocking show slave status.

[Laurynas Biveinis (laurynas-biveinis)]

Thanks Monty for catching this. http://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-6.html does not say that yet.

[monty solomon (monty+launchpad)]

We experience multiple failures due to this bug every day.

What are the plans for incorporating the fix for this bug in Percona Server?

Will the fix be backported into version 5.6.22?

What is the anticipated release date for version 5.6.23?

Thanks.

[Laurynas Biveinis (laurynas-biveinis)]

We are not planning to make another 5.6.22 release and are working on 5.6.23. The usual release deadline - no later than one month after a corresponding Oracle release - applies.

[monty solomon (monty+launchpad)]

I asked about 5.6.22 because I saw the milestone for 5.6.22-72.1 and thought it was in progress.

Thanks for the update.

[monty solomon (monty+launchpad)]

This bug was fixed in upstream and therefore should be fixed in 5.6.23-72.1 but it is not mentioned in the release notes at

http://www.percona.com/doc/percona-server/5.6/release-notes/Percona-Server-5.6.23-72.1.html

The upstream release notes state bug #19843808 was fixed.

http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-23.html

See the 12 Feb comment on bug #70307.

http://bugs.mysql.com/bug.php?id=70307

[Laurynas Biveinis (laurynas-biveinis)]

We missed updating of 5.6.23 upstream bugs in our tracker, thanks for catching this.

[Marcelo Henrique Gonçalves (billmask)]

Hi,

I am facing the same issue with a slave in the following version:
Server version: 5.6.30-76.3-log Percona Server (GPL), Release 76.3, Revision 3850db5

I am attaching some details as show processlist, status, packages, innodb status.

[Marcelo Henrique Gonçalves (billmask)]

It is related to the fact that relay log dir got 100% full? Cleaning it , stop slave, reset slave and change master to same position seems to have solved the problem.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-840