Bug #80607 main.log_tables-big unstable on loaded hosts
Submitted: 3 Mar 2016 14:25 Modified: 11 Nov 2016 16:15
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Server Severity:S3 (Non-critical)
Version:5.5,5.6,5.7 OS:Any
Assigned to: CPU Architecture:Any
Tags: mtr

[3 Mar 2016 14:25] Laurynas Biveinis
Description:
main.log_tables-big                      w4 [ fail ]
        Test ended at 2016-03-02 10:44:16

CURRENT_TEST: main.log_tables-big
--- /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/debian-jessie-64bit/mysql-test/r/log_tables-big.result	2016-03-01 19:44:59.428030231 +0300
+++ /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/debian-jessie-64bit/build/mysql-test/var/4/log/log_tables-big.reject	2016-03-02 18:44:16.183238108 +0300
@@ -24,6 +24,7 @@
 0
 select if (query_time between '00:01:40' and '00:01:50', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
 qt	sql_text
+WRONG	truncate table mysql.slow_log
 OK	select get_lock('bug27638', 101)
 select release_lock('bug27638');
 release_lock('bug27638')

The gist of the testcase is

truncate table mysql.slow_log;
select get_lock('bug27638', 2);
select if (query_time between '00:00:01' and '00:00:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
... repeated with different get_lock timeouts ...

Two things can go wrong here, on a very loaded host:
1) truncate table may take >1 s to complete, getting logged into slow log table as in the output above
2) get_lock may take than timeout + 10 s to complete

How to repeat:
Testcase analysis. Not sure if MTR --repeat --parallel high on this testcase alone will help to repeat as the testcase spends most of the time sleeping.

Suggested fix:
1) add WHERE sql_text = "get_lock ... " to the mysql.slow_log selects
2) test only the lower time bound
[4 Mar 2016 7:55] Umesh Shastry
Hello Laurynas,

Thank you for the report.
Observed this with 5.6.31 daily build.

Thanks,
Umesh
[7 Mar 2016 16:44] Laurynas Biveinis
Bug 80607 fix

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug80607.patch (application/octet-stream, text), 2.84 KiB.

[14 Oct 2016 5:37] Anitha Gopi
Posted by developer:
 
This test was disabled for a long time. It was fixed and enabled on MySQL 5.7 - bug#11756699. Evaluate if that fix was similar or if this contribution should be accepted
[14 Oct 2016 5:46] Laurynas Biveinis
The commit for 11756699 changes log destination to TABLE, whereas my patch filters the slow log for get_lock only (so that other testsuite commands running unexpectedly slowly do not interfere), and removes the upper time bound for get_lock, as it may be arbitrarily slow on a loaded host. Thus unless I am missing something, 11756699 commit and my fix are unrelated.
[11 Nov 2016 16:15] Paul Dubois
Posted by developer:
 
Noted in 5.5.55, 5.6.36, 5.7.18, 8.0.1 changelogs.

The main.log_tables-big test case could be unstable on highly loaded
hosts. Thanks to Laurynas Biveinis for the patch.