[MDEV-16561] rpl.rpl_non_direct_row_mixing_engines failed in buildbot with timeout in master_pos_wait Created: 2018-06-25  Updated: 2023-07-31  Resolved: 2023-07-31

Status: Closed
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 10.1
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1833/steps/mtr_nm/logs/stdio

rpl.rpl_non_direct_row_mixing_engines 'row,xtradb' w2 [ fail ]
 
        Test ended at 2018-05-27 02:17:15
 
 
 
CURRENT_TEST: rpl.rpl_non_direct_row_mixing_engines
 
=== SHOW MASTER STATUS ===
 
---- 1. ----
 
File	slave-bin.000001
 
Position	153157
 
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	16020
 
Connect_Retry	1
 
Master_Log_File	master-bin.000001
 
Read_Master_Log_Pos	186436
 
Relay_Log_File	slave-relay-bin.000002
 
Relay_Log_Pos	154086
 
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	153797
 
Relay_Log_Space	187023
 
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	402
 
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_SSL_Crl	
Master_SSL_Crlpath	
Using_Gtid	No
 
Gtid_IO_Pos	
Replicate_Do_Domain_Ids	
Replicate_Ignore_Domain_Ids	
Parallel_Mode	conservative
 
=========================
 
 
 
=== SHOW PROCESSLIST ===
 
---- 1. ----
 
Id	4
 
User	root
 
Host	localhost:45332
 
db	test
 
Command	Sleep
 
Time	1095
 
State	
Info	
Progress	0.000
 
---- 2. ----
 
Id	5
 
User	root
 
Host	localhost:45334
 
db	test
 
Command	Sleep
 
Time	1095
 
State	
Info	
Progress	0.000
 
---- 3. ----
 
Id	6
 
User	system user
 
Host	
db	
Command	Connect
 
Time	1095
 
State	Waiting for master to send event
 
Info	
Progress	0.000
 
---- 4. ----
 
Id	7
 
User	system user
 
Host	
db	test
 
Command	Connect
 
Time	401
 
State	Unlocking tables
 
Info	DROP TABLE IF EXISTS `tt_xx_7`,`nt_xx_7` /* generated by server */
 
Progress	0.000
 
---- 5. ----
 
Id	8
 
User	root
 
Host	localhost:45346
 
db	test
 
Command	Query
 
Time	0
 
State	init
 
Info	SHOW PROCESSLIST
 
Progress	0.000
 
---- 6. ----
 
Id	9
 
User	root
 
Host	localhost:45348
 
db	test
 
Command	Sleep
 
Time	1095
 
State	
Info	
Progress	0.000
 
========================
 
 
 
analyze: sync_with_master
 
mysqltest: In included file "./extra/rpl_tests/rpl_mixing_engines.test": 
included from /mnt/buildbot/build/mariadb-10.1.34/mysql-test/suite/rpl/t/rpl_non_direct_row_mixing_engines.test at line 15:
 
At line 1803: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 186436, 300, '')' returned -1 indicating timeout after 300 seconds
 
 
 
The result from queries just before the failure was:
 
< snip >
 
-e-e-e-e-e-e-e-e-e-e-e- >> set-NT << -e-e-e-e-e-e-e-e-e-e-e-
 
-b-b-b-b-b-b-b-b-b-b-b- >> R << -b-b-b-b-b-b-b-b-b-b-b-
 
ROLLBACK;
 
Warnings:
 
Warning	#	Some non-transactional changed tables couldn't be rolled back
 
include/show_binlog_events.inc
 
-e-e-e-e-e-e-e-e-e-e-e- >> R << -e-e-e-e-e-e-e-e-e-e-e-
 
-b-b-b-b-b-b-b-b-b-b-b- >> B set-T set-NT R << -b-b-b-b-b-b-b-b-b-b-b-
 
include/show_binlog_events.inc
 
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 
master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
master-bin.000001	#	Table_map	#	#	table_id: # (test.nt_3)
 
master-bin.000001	#	Table_map	#	#	table_id: # (test.nt_3)
 
master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
 
master-bin.000001	#	Query	#	#	COMMIT
 
-e-e-e-e-e-e-e-e-e-e-e- >> B set-T set-NT R << -e-e-e-e-e-e-e-e-e-e-e-
 
 
 
###################################################################################
 
#                               CHECK CONSISTENCY 
###################################################################################
 
 
 
More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/log/rpl_non_direct_row_mixing_engines.log
 
 
 
 
 
 == /mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/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
 
2018-05-27 02:17:14	1
 
 
 
**** SHOW SLAVE STATUS on default ****
 
SHOW SLAVE STATUS;
 
 
 
**** SHOW MASTER STATUS on default ****
 
SHOW MASTER STATUS;
 
File	master-bin.000001
 
Position	186436
 
Binlog_Do_DB	
Binlog_Ignore_DB	
 
 
**** SHOW SLAVE HOSTS on default ****
 
SHOW SLAVE HOSTS;
 
Server_id	2
 
Host	127.0.0.1
 
Port	16021
 
Master_id	1
 
 
 
**** SHOW PROCESSLIST on default ****
 
SHOW PROCESSLIST;
 
Id	User	Host	db	Command	Time	State	Info	Progress
 
7	root	localhost:40082	NULL	Binlog Dump	1100	Master has sent all binlog to slave; waiting for binlog to be updated	NULL	0.000
 
1739	root	localhost	NULL	Query	0	init	SHOW PROCESSLIST	0.000
 
 
 
**** SHOW BINARY LOGS on default ****
 
SHOW BINARY LOGS;
 
Log_name	File_size
 
master-bin.000001	186436
 
 
 
**** 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	249	Server ver: 10.1.34-MariaDB, Binlog ver: 4
 
master-bin.000001	249	Gtid_list	1	274	[]
 
master-bin.000001	274	Binlog_checkpoint	1	314	master-bin.000001
 
master-bin.000001	314	Gtid	1	352	BEGIN GTID 0-1-1
 
master-bin.000001	352	Table_map	1	409	table_id: 30 (mtr.test_suppressions)
 
master-bin.000001	409	Write_rows_v1	1	537	table_id: 30 flags: STMT_END_F
 
master-bin.000001	537	Query	1	605	COMMIT
 
<...>
 
master-bin.000001	186311	Write_rows_v1	1	186367	table_id: 33 flags: STMT_END_F
 
master-bin.000001	186367	Query	1	186436	COMMIT
 
 
 
**** 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/buildbot/build/mariadb-10.1.34/mysql-test/var/2/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
 
2018-05-27 02:17:14	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	16020
 
Connect_Retry	1
 
Master_Log_File	master-bin.000001
 
Read_Master_Log_Pos	186436
 
Relay_Log_File	slave-relay-bin.000002
 
Relay_Log_Pos	154086
 
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	153797
 
Relay_Log_Space	187023
 
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	406
 
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_SSL_Crl	
Master_SSL_Crlpath	
Using_Gtid	No
 
Gtid_IO_Pos	
Replicate_Do_Domain_Ids	
Replicate_Ignore_Domain_Ids	
Parallel_Mode	conservative
 
 
 
**** SHOW MASTER STATUS on default ****
 
SHOW MASTER STATUS;
 
File	slave-bin.000001
 
Position	153157
 
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	Progress
 
6	system user		NULL	Connect	1100	Waiting for master to send event	NULL	0.000
 
7	system user		test	Connect	406	Unlocking tables	DROP TABLE IF EXISTS `tt_xx_7`,`nt_xx_7` /* generated by server */	0.000
 
10	root	localhost	NULL	Query	0	init	SHOW PROCESSLIST	0.000
 
 
 
**** SHOW BINARY LOGS on default ****
 
SHOW BINARY LOGS;
 
Log_name	File_size
 
slave-bin.000001	153157
 
 
 
<...>
 
 
 
 
 
 - saving '/mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/log/rpl.rpl_non_direct_row_mixing_engines-row,xtradb/' to '/mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/log/rpl.rpl_non_direct_row_mixing_engines-row,xtradb/'
 
worker[2] > Restart  - not started
 
worker[2] > Restart  - not started
 
***Warnings generated in error logs during shutdown after running tests: rpl.rpl_non_direct_row_mixing_engines
 
 
 
InnoDB: Error: Waited for 5 secs for hash index ref_count (1) to drop to 0.
 
InnoDB: Error: Waited for 10 secs for hash index ref_count (1) to drop to 0.
 
<...>
 
InnoDB: Error: Waited for 235 secs for hash index ref_count (1) to drop to 0.
 
InnoDB: Warning: semaphore wait:
 
InnoDB: Error: Waited for 240 secs for hash index ref_count (1) to drop to 0.
 
<...>
 
 
 
InnoDB: Error: Waited for 395 secs for hash index ref_count (1) to drop to 0.



 Comments   
Comment by Roel Van de Paar [ 2023-07-31 ]

The issue in this ticket is not that the tests are slow, but that a particular timeout failure occurred in rpl.rpl_non_direct_row_mixing_engines using xtradb in the now unsupported 10.1 release of MariaDB, and this in 2018. xtradb is no longer used, 10.1 is no longer used, and I have tested rpl.rpl_non_direct_row_mixing_engines, and this issue was not observed anymore. Closing ticket.

Generated at Thu Feb 08 08:29:50 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.