[MDEV-32184] rpl.rpl_gtid_until_before_after_gtids regularly times out - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 11.3
Fix Version/s: 11.3.1
Component/s: Replication
Labels:
- timeout

Description

Using:

MTR_MEM=/dev/shm ./mysql-test-run --repeat=99999 --parallel=30 --mem --force --retry=99999 --retry-failure=99999 rpl_gtid_until_before_after_gtids | tee mtr_output.txt

We see regular timeouts in rpl_gtid_until_before_after_gtids on both optimized and debug builds:

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (debug)
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 144 pass ] 3206
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 146 pass ] 2617
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 145 pass ] 3344
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 147 pass ] 3260
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w15 [ 72 fail ]
Test ended at 2023-09-12 16:15:58

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids
mysqltest: In included file "./include/wait_for_slave_param.inc":
included from ./include/wait_for_slave_io_to_start.inc at line 40:
included from ./include/wait_for_slave_to_start.inc at line 26:
included from ./include/start_slave.inc at line 35:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/suite/rpl/include/rpl_gtid_until_before_after_gtids.test at line 161:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/suite/rpl/t/rpl_gtid_until_before_after_gtids.test at line 26:
At line 119: Timeout in include/wait_for_slave_param.inc

The result from queries just before the failure was:
< snip >
master-bin.000001 1397 Annotate_rows 1 1447 INSERT INTO t1 VALUES (103)
master-bin.000001 1447 Table_map 1 1492 table_id: 459 (test.t1)
master-bin.000001 1492 Write_rows_v1 1 1530 table_id: 459 flags: STMT_END_F
master-bin.000001 1530 Query 1 1603 COMMIT
master-bin.000001 1603 Gtid 1 1645 BEGIN GTID 0-1-7
master-bin.000001 1645 Annotate_rows 1 1695 INSERT INTO t1 VALUES (104)
master-bin.000001 1695 Table_map 1 1740 table_id: 459 (test.t1)
master-bin.000001 1740 Write_rows_v1 1 1778 table_id: 459 flags: STMT_END_F
master-bin.000001 1778 Query 1 1851 COMMIT
master-bin.000001 1851 Gtid 1 1893 BEGIN GTID 0-1-9
master-bin.000001 1893 Annotate_rows 1 1943 INSERT INTO t1 VALUES (105)
master-bin.000001 1943 Table_map 1 1988 table_id: 459 (test.t1)
master-bin.000001 1988 Write_rows_v1 1 2026 table_id: 459 flags: STMT_END_F
master-bin.000001 2026 Query 1 2099 COMMIT

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

More results from queries before failure can be found in /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/15/log/rpl_gtid_until_before_after_gtids.log

- saving '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/15/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/' to '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/'

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (optimized)
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 238 pass ] 2614
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 239 pass ] 2393
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 240 pass ] 2891
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w9 [ 157 fail ]
Test ended at 2023-09-12 16:20:16

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids
mysqltest: In included file "./include/wait_for_slave_param.inc":
included from ./include/wait_for_slave_io_to_start.inc at line 40:
included from ./include/wait_for_slave_to_start.inc at line 26:
included from ./include/start_slave.inc at line 35:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/suite/rpl/include/rpl_gtid_until_before_after_gtids.test at line 161:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/suite/rpl/t/rpl_gtid_until_before_after_gtids.test at line 29:
At line 119: Timeout in include/wait_for_slave_param.inc

The result from queries just before the failure was:
< snip >
master-bin.000001 1397 Annotate_rows 1 1447 INSERT INTO t1 VALUES (114)
master-bin.000001 1447 Table_map 1 1492 table_id: 971 (test.t1)
master-bin.000001 1492 Write_rows_v1 1 1530 table_id: 971 flags: STMT_END_F
master-bin.000001 1530 Query 1 1603 COMMIT
master-bin.000001 1603 Gtid 1 1645 BEGIN GTID 0-1-7
master-bin.000001 1645 Annotate_rows 1 1695 INSERT INTO t1 VALUES (115)
master-bin.000001 1695 Table_map 1 1740 table_id: 971 (test.t1)
master-bin.000001 1740 Write_rows_v1 1 1778 table_id: 971 flags: STMT_END_F
master-bin.000001 1778 Query 1 1851 COMMIT
master-bin.000001 1851 Gtid 1 1893 BEGIN GTID 0-1-9
master-bin.000001 1893 Annotate_rows 1 1943 INSERT INTO t1 VALUES (116)
master-bin.000001 1943 Table_map 1 1988 table_id: 971 (test.t1)
master-bin.000001 1988 Write_rows_v1 1 2026 table_id: 971 flags: STMT_END_F
master-bin.000001 2026 Query 1 2099 COMMIT

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

More results from queries before failure can be found in /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/9/log/rpl_gtid_until_before_after_gtids.log

- saving '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/9/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/' to '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/'

Issues are somewhat regular:

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (debug)
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w15 [ 72 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 176 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 1000 fail ]

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (optimized)
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w9 [ 157 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 167 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 242 fail ]

And we also see regular retry failures (38 out of 5536 on debug, 49 out of 6361 on optimized). Note the test suite will timeout around 5-6K execs depending on system performance.

Attachments

Issue Links

blocks

MDEV-27247 Add keywords "SQL_BEFORE_GTIDS" and "SQL_AFTER_GTIDS" for START SLAVE UNTIL

Closed

is caused by

MDEV-27247 Add keywords "SQL_BEFORE_GTIDS" and "SQL_AFTER_GTIDS" for START SLAVE UNTIL

Closed

Activity

People

Assignee:: Brandon Nesterenko

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2023-09-16 03:00

Updated:: 2023-10-18 04:27

Resolved:: 2023-10-14 05:39

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.