Bug #39861 binlog_killed times out sporadically on pushbuild
Submitted: 4 Oct 2008 14:12 Modified: 17 Feb 2009 17:20
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S7 (Test Cases)
Version:5.1, 6.0 OS:Any
Assigned to: Serge Kozlov CPU Architecture:Any
Tags: binlog_killed, disabled, pushbuild, sporadic, test failure, timeout

[4 Oct 2008 14:12] Sven Sandberg
Description:
binlog_killed times out sporadically on pushbuild:

binlog.binlog_killed                     [ fail ]  timeout after 15 minutes

Test case timeout after 15 minute(s)

Timeout [timer - pid: 2336, exit: 0] expired for running 'analyze-timeout'
 - saving 'e:/var-n_mix-100/log/binlog.binlog_killed/' to 'e:/var-n_mix-100/log/binlog.binlog_killed/'

Retrying test, attempt(2/3)...

How to repeat:
Happens in all trees, both 5.1 and 6.0, only on windows. Here's one example:

https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-5.1-rpl&order=55 vm-win2003-64-b/n_mix

xref: http://tinyurl.com/4ojpnq

Suggested fix:
I suggest checking the test case carefully. If nothing suspicious is found, try to think of some way to augment either mtr or the test case that would give more information when the test fails next time.
[12 Nov 2008 20:02] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58580

2692 Serge Kozlov	2008-11-12
      Bug#39861:
      1. mysqltest.cc - added flush to log file after each executed command in a test case. 
      2. mtr shows 20 last lines from test case log file if timeout reached.
[13 Nov 2008 20:22] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58701

2692 Serge Kozlov	2008-11-13
      Bug#39861:
      1. mysqltest.cc - added flush to log file after each executed command in a testcase. 
      2. mtr shows 20 last lines from test case log file if timeout reached.
      3. Optimizing the code by Magnus review.
      4. It is partially fix bug#40150
[14 Nov 2008 10:12] Lars Thalmann
Unsetting Magnus review flag, since the patch that Magnus approved is
not the complete solution for this bug.

Serge will push the MTR/mysqltest improvement.
[14 Nov 2008 20:36] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58844

2698 Serge Kozlov	2008-11-14
      Bug#39861:
      1. mysqltest.cc - added flush to log file after each executed command in a testcase.
      2. mtr shows 20 last lines from test case log file if timeout reached.
      3. Optimizing the code by Magnus review.
      4. It is partially fix bug#40150
[14 Nov 2008 21:45] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58853

2699 Serge Kozlov	2008-11-15
      fix for bug#39861
[15 Nov 2008 11:41] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58868

2700 Serge Kozlov	2008-11-15
      Bug#39861, added comment to mtr
[15 Nov 2008 11:43] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58869

2734 Serge Kozlov	2008-11-15 [merge]
      Bug#39861, added comment for mtr and fix
[19 Nov 2008 14:48] Sven Sandberg
The patch did not fix the timeout, it only made mtr print better debug info when it happens next time. Setting status to "to be fixed later". The bug should be fixed when it fails next time with this new debug info.
[8 Dec 2008 12:33] Alexander Nozdrin
binlog_killed.test is disabled due to this bug.
[19 Dec 2008 8:24] Sven Sandberg
The test has now failed again, with debug info:

binlog.binlog_killed                     [ fail ]  timeout after 900 seconds
        Test ended at 2008-12-04 19:20:19

Test case timeout after 900 seconds

== e:/var-n_mix-100/log/binlog_killed.log == 
create table t4 (a int, b int) ENGINE=MyISAM /* for killing update and delete */;
create function bug27563(n int) 
RETURNS int(11)
DETERMINISTIC
begin
if @b > 0 then
select get_lock("a", 20)  into @a;
else 
set @b= 1;
end if;
return n;
end|
delete from t4;
insert into t4 values (1,1), (1,1);
reset master;
select get_lock("a", 20);
get_lock("a", 20)
1
set @b= 0;
update t4 set b=b + bug27563(b);

Timeout [timer - pid: 6096, exit: 0] for 'analyze-timeout' expired after 90 seconds
 - saving 'e:/var-n_mix-100/log/binlog.binlog_killed/' to 'e:/var-n_mix-100/log/binlog.binlog_killed/'

Retrying test, attempt(2/3)...
[30 Jan 2009 13:30] Bugs System
Pushed into 6.0.10-alpha (revid:luis.soares@sun.com-20090129165607-wiskabxm948yx463) (version source revid:luis.soares@sun.com-20090129163120-e2ntks4wgpqde6zt) (merge vers: 6.0.10-alpha) (pib:6)
[30 Jan 2009 15:10] Bugs System
Pushed into 5.1.32 (revid:luis.soares@sun.com-20090129165946-d6jnnfqfokuzr09y) (version source revid:skozlov@mysql.com-20081115114040-w3j5k569n3yl7tn1) (merge vers: 5.1.31) (pib:6)
[15 Feb 2009 11:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/66397

3047 Serge Kozlov	2009-02-15
      Bug#39861. Re-enabled because fixed by MTR2 patch
      modified:
        mysql-test/suite/binlog/t/disabled.def

=== modified file 'mysql-test/suite/binlog/t/disabled.def'
--- a/mysql-test/suite/binlog/t/disabled.def	2009-02-09 23:03:35 +0000
+++ b/mysql-test/suite/binlog/t/disabled.def	2009-02-15 11:45:53 +0000
@@ -14,5 +14,4 @@ binlog_truncate_innodb	: BUG#42643 2009-
 binlog_multi_engine     : Bug#30544 istruewing 2007-11-26
 binlog_row_ctype_cp932  : Bug#33376 2007-12-19 mats Write set for table not set correctly when inserting an empty set
 binlog_base64_flag      : Bug#38316 sven 2007-12-14
-binlog_killed           : Bug#39861 kostja 2008-04-20
 binlog_killed_simulate  : Bug#37932 kostja 2008-04-20

-- 
MySQL Code Commits Mailing List
For list archives: http://lists.mysql.com/commits
To unsubscribe:    http://lists.mysql.com/commits?unsub=commits@bugs.mysql.com
[17 Feb 2009 14:59] Bugs System
Pushed into 5.1.32-ndb-6.3.23 (revid:tomas.ulin@sun.com-20090217131017-6u8qz1edkjfiobef) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)
[17 Feb 2009 16:46] Bugs System
Pushed into 5.1.32-ndb-6.4.3 (revid:tomas.ulin@sun.com-20090217134419-5ha6xg4dpedrbmau) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)
[17 Feb 2009 17:20] Jon Stephens
No user-facing changes to document; testing changes only. Closed w/o further action.
[17 Feb 2009 18:23] Bugs System
Pushed into 5.1.32-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090217134216-5699eq74ws4oxa0j) (version source revid:tomas.ulin@sun.com-20090201210519-vehobc4sy3g9s38e) (merge vers: 5.1.32-ndb-6.2.17) (pib:6)
[19 Feb 2009 13:03] Bugs System
Pushed into 6.0.10-alpha (revid:sergey.glukhov@sun.com-20090218125737-5y5b2xo3duo1wlvo) (version source revid:serge.kozlov@sun.com-20090215114553-kluaanoy1qk497dl) (merge vers: 6.0.10-alpha) (pib:6)