Bug #73736 Missing testcase sync in rpl_err_ignoredtable
Submitted: 27 Aug 2014 6:28 Modified: 18 Mar 2015 10:28
Reporter: Laurynas Biveinis Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Tests Severity:S3 (Non-critical)
Version: OS:Any
Assigned to: CPU Architecture:Any
Tags: mtr

[27 Aug 2014 6:28] Laurynas Biveinis
Description:
rpl_err_ignoredtable test has a race causing spurious failure.connection master1;
select get_lock('crash_lock%20C', 10);

connection master;
...
send update t2 set a = a + 1 + get_lock('crash_lock%20C', 10);

connection master1;
...
kill @id;
drop table t2,t3;
...
connection master;
# The get_lock function causes warning for unsafe statement.
--disable_warnings
--error 0,1317,2013
reap;

KILL and DROP TABLE statements race and may end up in the master1
thread holding the user lock and attempting to drop the tables, while
the master thread hasn't reacted to the kill bit yet, and thus has the
same tables locked and is waiting for the user lock.

How to repeat:
We have seen this failure in Percona Server 5.6 CI runs. For example,

http://jenkins.percona.com/job/percona-server-5.6-trunk/312/BUILD_TYPE=release,Host=ubuntu...

Logfile:
CURRENT_TEST: rpl.rpl_err_ignoredtable
mysqltest: At line 50: query 'drop table t2,t3' failed: 1213: Deadlock found when trying to get lock; try restarting transaction

The result from queries just before the failure was:
< snip >
Tables_in_test (t4)
t4
SELECT * FROM test.t4 ORDER BY a;
a
1
2
drop table t1;
include/sync_slave_sql_with_master.inc
select get_lock('crash_lock%20C', 10);
get_lock('crash_lock%20C', 10)
1
create table t2 (a int primary key);
insert into t2 values(1);
create table t3 (id int);
insert into t3 values(connection_id());
update t2 set a = a + 1 + get_lock('crash_lock%20C', 10);
select (@id := id) - id from t3;
(@id := id) - id
0
kill @id;

MariaDB must have seen this as well, since they have fixed this.

Suggested fix:
Wait after KILL statement.
[27 Aug 2014 12:39] MySQL Verification Team
On Windows with latest source:

C:\2014.08.24\mysql-5.6\mysql-test>perl mysql-test-run.pl rpl_err_ignoredtable
Found handle.exe version 3.51
Logging: mysql-test-run.pl  rpl_err_ignoredtable
2014-08-27 09:33:00 6148 [Note] Plugin 'FEDERATED' is disabled.
2014-08-27 09:33:00 6148 [Note] Binlog end
2014-08-27 09:33:00 6148 [Note] Shutting down plugin 'MyISAM'
2014-08-27 09:33:00 6148 [Note] Shutting down plugin 'CSV'
MySQL Version 5.6.21
Checking supported features...
 - SSL connections supported
Collecting tests...
 - adding combinations for rpl
Removing old var directory...
Creating var directory 'C:/2014.08.24/mysql-5.6/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_err_ignoredtable 'mix'           [ pass ]  14087
rpl.rpl_err_ignoredtable 'row'           [ pass ]  13167
rpl.rpl_err_ignoredtable 'stmt'          [ pass ]  12776
--------------------------------------------------------------------------
The servers were restarted 2 times
Spent 40.030 of 111 seconds executing testcases

Completed: All 3 tests were successful.
[27 Aug 2014 12:57] MySQL Verification Team
On Linux Mint

miguel@lara ~/build/mysql-5.6/mysql-test $ ./mtr rpl_err_ignoredtable
Logging: ./mtr  rpl_err_ignoredtable
2014-08-27 09:53:56 2642 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2014-08-27 09:53:56 2642 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

2014-08-27 09:53:56 2642 [Note] Plugin 'FEDERATED' is disabled.
2014-08-27 09:53:56 2642 [Note] Binlog end
2014-08-27 09:53:56 2642 [Note] Shutting down plugin 'CSV'
2014-08-27 09:53:56 2642 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.22
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
 - adding combinations for rpl
Removing old var directory...
Creating var directory '/home/miguel/build/mysql-5.6/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_err_ignoredtable 'mix'           [ pass ]  12752
rpl.rpl_err_ignoredtable 'row'           [ pass ]  12633
rpl.rpl_err_ignoredtable 'stmt'          [ pass ]  12653
--------------------------------------------------------------------------
The servers were restarted 2 times
Spent 38.038 of 72 seconds executing testcases

Completed: All 3 tests were successful.
[27 Aug 2014 13:58] Laurynas Biveinis
It is very much an intermittent failure. Unfortunately I don't have a reliable reproduction procedure.
[27 Aug 2014 14:42] MySQL Verification Team
Cmake compile options maybe?.
[28 Aug 2014 5:37] Laurynas Biveinis
The CMake options were -DCMAKE_BUILD_TYPE=RelWithDebInfo -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DENABLE_DTRACE=OFF -DENABLE_DOWNLOADS=1 -DWITH_EXAMPLE_STORAGE_ENGINE=ON -DWITH_SSL=system.

I doubt they will help though. It's more likely to occur on a loaded build host, and even then it's a low probability. If you cannot Verify this by testcase analysis, then I guess this will have to wait until you encounter a failure instance.
[4 Mar 2015 12:03] Laurynas Biveinis
This has been fixed in 5.7 with the multiple GET_LOCK patch 010811852fb66d5bccd42ebd84c263aba0157f9c:

+eval kill $master_id;
+# Wait until it is safe to issue DROP TABLE without causing deadlock.
+# let $wait_condition= SELECT count(*) = 0 FROM information_schema.processlist
+#                      WHERE info LIKE 'update%' AND state = 'User lock';
+let $wait_condition= SELECT count(*) = 0 FROM information_schema.processlist
+                     WHERE id = $master_id;
+--source include/wait_condition_or_abort.inc
[18 Mar 2015 0:32] MySQL Verification Team
According your last comment this issue can be closed right?. Thanks.
[18 Mar 2015 7:02] Laurynas Biveinis
Yes, as fixed in 5.7.5.
[18 Mar 2015 10:28] MySQL Verification Team
Thank you for the feedback.