Percona Server moved to https://jira.percona.com/projects/PS

Test percona_show_slave_status_nolock is unstable

Bug #1608845 reported by Laurynas Biveinis
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Fix Released
Low
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.5.51-38.1
5.6
Fix Released
Low
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.6.32-78.0
5.7
Invalid
Undecided
Laurynas Biveinis

Bug Description

main.percona_show_slave_status_nolock w4 [ fail ]
        Test ended at 2016-08-01 09:01:47

CURRENT_TEST: main.percona_show_slave_status_nolock
=== SHOW MASTER STATUS ===
---- 1. ----
File slave-bin.000001
Position 1167
Binlog_Do_DB
Binlog_Ignore_DB
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State Waiting for master to send event
Master_Host 127.0.0.1
Master_User root
Master_Port 13021
Connect_Retry 1
Master_Log_File master-bin.000001
Read_Master_Log_Pos 1270
Relay_Log_File slave-relay-bin.000003
Relay_Log_Pos 357
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 1270
Relay_Log_Space 1720
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 0
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
=========================

=== SHOW PROCESSLIST ===
---- 1. ----
Id 18
User root
Host localhost:50759
db test
Command Sleep
Time 303
State
Info
Rows_sent 1
Rows_examined 0
Rows_read 0
---- 2. ----
Id 19
User root
Host localhost:50761
db test
Command Sleep
Time 303
State
Info
Rows_sent 1
Rows_examined 0
Rows_read 0
---- 3. ----
Id 22
User root
Host localhost:50774
db test
Command Query
Time 0
State
Info SHOW PROCESSLIST
Rows_sent 0
Rows_examined 0
Rows_read 0
---- 4. ----
Id 23
User root
Host localhost:50775
db test
Command Sleep
Time 303
State
Info
Rows_sent 1
Rows_examined 0
Rows_read 0
---- 5. ----
Id 24
User root
Host localhost:50776
db test
Command Sleep
Time 302
State
Info
Rows_sent 0
Rows_examined 0
Rows_read 0
---- 6. ----
Id 25
User root
Host localhost:50777
db test
Command Sleep
Time 301
State
Info
Rows_sent 0
Rows_examined 0
Rows_read 0
---- 7. ----
Id 26
User root
Host localhost:50792
db test
Command Sleep
Time 300
State
Info
Rows_sent 1
Rows_examined 0
Rows_read 0
---- 8. ----
Id 27
User system user
Host
db
Command Connect
Time 300
State Waiting for master to send event
Info
Rows_sent 0
Rows_examined 0
Rows_read 0
---- 9. ----
Id 28
User system user
Host
db
Command Connect
Time 300
State Slave has read all relay log; waiting for the slave I/O thread to update it
Info
Rows_sent 0
Rows_examined 0
Rows_read 0
========================

analyze: sync_with_master
mysqltest: At line 88: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 1270, 300)' returned -1 indicating timeout after 300 seconds

The result from queries just before the failure was:
< snip >
SHOW SLAVE STATUS NOLOCK;
SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
# should be 'signal.after_show_slave_status'
SIGNAL after SHOW SLAVE STATUS NOLOCK is 'signal.after_show_slave_status'
[slave]
SET DEBUG_SYNC='now SIGNAL signal.continue';
[slave]
SET DEBUG_SYNC='now SIGNAL signal.empty';

[slave_stop]
include/wait_for_slave_to_stop.inc
START SLAVE;
include/wait_for_slave_to_start.inc
[master]
SET DEBUG_SYNC='RESET';
[slave]
SET GLOBAL DEBUG='';
SET DEBUG_SYNC='RESET';
[master]
DROP TABLE t;

More results from queries before failure can be found in /mnt/workspace/percona-server-5.5-param/BUILD_TYPE/debug/Host/centos5-64/mysql-test/var/4/log/percona_show_slave_status_nolock.log
safe_process[24464]: Child process: 24465, exit: 1

 == /mnt/workspace/percona-server-5.5-param/BUILD_TYPE/debug/Host/centos5-64/mysql-test/var/4/tmp/analyze-sync_with_master-mysqld.1.err ==

############################## default ##############################

**** SHOW WARNINGS on default ****
SHOW WARNINGS;
Level Code Message

**** SELECT replication-related variables on default ****
SELECT NOW(), @@SERVER_ID;
NOW() @@SERVER_ID
2016-08-01 16:01:47 1

**** SHOW SLAVE STATUS on default ****
SHOW SLAVE STATUS;

**** SHOW MASTER STATUS on default ****
SHOW MASTER STATUS;
File master-bin.000001
Position 1270
Binlog_Do_DB
Binlog_Ignore_DB

**** SHOW SLAVE HOSTS on default ****
SHOW SLAVE HOSTS;
Server_id 2
Host 127.0.0.1
Port 13022
Master_id 1

**** SHOW PROCESSLIST on default ****
SHOW PROCESSLIST;
Id User Host db Command Time State Info Rows_sent Rows_examined Rows_read
17 root localhost:33468 NULL Binlog Dump 300 Master has sent all binlog to slave; waiting for binlog to be updated NULL 0 0 0
18 root localhost NULL Query 0 NULL SHOW PROCESSLIST 0 0 0

**** SHOW BINARY LOGS on default ****
SHOW BINARY LOGS;
Log_name File_size
master-bin.000001 1270

**** SHOW BINLOG EVENTS on default ****
binlog_name = 'master-bin.000001'
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
master-bin.000001 4 Format_desc 1 107 Server ver: 5.5.50-38.0-debug-log, Binlog ver: 4
master-bin.000001 107 Query 1 174 BEGIN
master-bin.000001 174 Query 1 455 use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Slave SQL: Request to stop slave SQL Thread received while applying a group that has non-transactional changes' COLLATE 'latin1_swedish_ci'))
master-bin.000001 455 Query 1 523 COMMIT
master-bin.000001 523 Query 1 636 use `test`; DROP TABLE IF EXISTS `t` /* generated by server */
master-bin.000001 636 Query 1 721 use `test`; CREATE TABLE t(id INT)
master-bin.000001 721 Query 1 789 BEGIN
master-bin.000001 789 Query 1 875 use `test`; INSERT INTO t VALUES(0)
master-bin.000001 875 Query 1 944 COMMIT
master-bin.000001 944 Query 1 1012 BEGIN
master-bin.000001 1012 Query 1 1098 use `test`; INSERT INTO t VALUES(1)
master-bin.000001 1098 Query 1 1167 COMMIT
master-bin.000001 1167 Query 1 1270 use `test`; DROP TABLE `t` /* generated by server */

**** SHOW RELAYLOG EVENTS on default ****
relaylog_name = 'No such row'
SHOW RELAYLOG EVENTS IN 'No such row';
Log_name Pos Event_type Server_id End_log_pos Info

 == /mnt/workspace/percona-server-5.5-param/BUILD_TYPE/debug/Host/centos5-64/mysql-test/var/4/tmp/analyze-sync_with_master-mysqld.2.err ==

############################## default ##############################

**** SHOW WARNINGS on default ****
SHOW WARNINGS;
Level Code Message

**** SELECT replication-related variables on default ****
SELECT NOW(), @@SERVER_ID;
NOW() @@SERVER_ID
2016-08-01 16:01:47 2

**** SHOW SLAVE STATUS on default ****
SHOW SLAVE STATUS;
Slave_IO_State Waiting for master to send event
Master_Host 127.0.0.1
Master_User root
Master_Port 13021
Connect_Retry 1
Master_Log_File master-bin.000001
Read_Master_Log_Pos 1270
Relay_Log_File slave-relay-bin.000003
Relay_Log_Pos 357
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 1270
Relay_Log_Space 1720
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 0
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

**** SHOW MASTER STATUS on default ****
SHOW MASTER STATUS;
File slave-bin.000001
Position 1270
Binlog_Do_DB
Binlog_Ignore_DB

**** SHOW SLAVE HOSTS on default ****
SHOW SLAVE HOSTS;

**** SHOW PROCESSLIST on default ****
SHOW PROCESSLIST;
Id User Host db Command Time State Info Rows_sent Rows_examined Rows_read
27 system user NULL Connect 300 Waiting for master to send event NULL 0 0 0
28 system user NULL Connect 300 Slave has read all relay log; waiting for the slave I/O thread to update it NULL 0 0 0
29 root localhost NULL Query 0 NULL SHOW PROCESSLIST 0 0 0

**** SHOW BINARY LOGS on default ****
SHOW BINARY LOGS;
Log_name File_size
slave-bin.000001 1270

**** SHOW BINLOG EVENTS on default ****
binlog_name = 'slave-bin.000001'
SHOW BINLOG EVENTS IN 'slave-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 4 Format_desc 2 107 Server ver: 5.5.50-38.0-debug-log, Binlog ver: 4
slave-bin.000001 107 Query 1 174 BEGIN
slave-bin.000001 174 Query 1 455 use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Slave SQL: Request to stop slave SQL Thread received while applying a group that has non-transactional changes' COLLATE 'latin1_swedish_ci'))
slave-bin.000001 455 Query 1 523 COMMIT
slave-bin.000001 523 Query 1 636 use `test`; DROP TABLE IF EXISTS `t` /* generated by server */
slave-bin.000001 636 Query 1 721 use `test`; CREATE TABLE t(id INT)
slave-bin.000001 721 Query 1 789 BEGIN
slave-bin.000001 789 Query 1 875 use `test`; INSERT INTO t VALUES(0)
slave-bin.000001 875 Query 1 944 COMMIT
slave-bin.000001 944 Query 1 1012 BEGIN
slave-bin.000001 1012 Query 1 1098 use `test`; INSERT INTO t VALUES(1)
slave-bin.000001 1098 Query 1 1167 COMMIT
slave-bin.000001 1167 Query 1 1270 use `test`; DROP TABLE `t` /* generated by server */

**** SHOW RELAYLOG EVENTS on default ****
relaylog_name = 'slave-relay-bin.000003'
SHOW RELAYLOG EVENTS IN 'slave-relay-bin.000003';
Log_name Pos Event_type Server_id End_log_pos Info
slave-relay-bin.000003 4 Format_desc 2 107 Server ver: 5.5.50-38.0-debug-log, Binlog ver: 4
slave-relay-bin.000003 107 Rotate 1 0 master-bin.000001;pos=1167
slave-relay-bin.000003 151 Format_desc 1 0 Server ver: 5.5.50-38.0-debug-log, Binlog ver: 4
slave-relay-bin.000003 254 Query 1 1270 use `test`; DROP TABLE `t` /* generated by server */

select master_pos_wait('master-bin.000001', 1270, 300) has timed out even though the RPL dump shows that the slave has already caught up to this position. This could be caused by SET GLOBAL debug= on slave with the slave running, similar to bug 1606782, bug 1607359.

Tags: ci
Laurynas Biveinis (laurynas-biveinis)
tags: added: ci
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

     https://github.com/percona/percona-server/pull/759
     https://github.com/percona/percona-server/pull/760
     https://github.com/percona/percona-server/pull/761

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.