Bug #46029 rpl_innodb_bug28430 times out on certain pb2 hosts
Submitted: 8 Jul 2009 7:18 Modified: 11 Mar 2014 7:26
Reporter: Georgi Kodinov Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version:5.1-bugteam, 5.1 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: experimental, pb2, sporadic, test failure

[8 Jul 2009 7:18] Georgi Kodinov
Description:
rpl.rpl_innodb_bug28430                  w8 [ fail ]  timeout after 900 seconds
        Test ended at 2009-07-08 00:23:13

Test case timeout after 900 seconds

== /export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/8/log/rpl_innodb_bug28430.log == 
SET local_time= NOW();
SET cur_user = CURRENT_USER();
SET local_uuid=UUID();
WHILE ins_count > 0 DO
INSERT INTO test.byrange_tbl VALUES (NULL, NOW(), USER(), UUID(),
ins_count,'Going to test MBR for MySQL');
SET ins_count = ins_count - 1;
END WHILE;
SELECT MAX(id) FROM test.byrange_tbl INTO del_count;
WHILE del_count > 0 DO
DELETE FROM test.byrange_tbl WHERE id = del_count;
SET del_count = del_count - 2;
END WHILE;
END|
CALL test.proc_norm();
SELECT count(*) as "Master regular" FROM test.regular_tbl;
Master regular	500
CALL test.proc_bykey();
SELECT count(*) as "Master bykey" FROM test.bykey_tbl;
Master bykey	500

 == /export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/8/tmp/analyze-timeout-mysqld.2.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/export/home/pb2/test/sb_6-630897-1247001400.61/tmp/hHn4nuW0iS/8/mysqld.2.sock' (146)

 == /export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/8/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/export/home/pb2/test/sb_6-630897-1247001400.61/tmp/hHn4nuW0iS/8/mysqld.1.sock' (146)

 - saving '/export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/8/log/rpl.rpl_innodb_bug28430/' to '/export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/log/rpl.rpl_innodb_bug28430/'
 - found 'core', moving it to '/export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/mysql-test/var/log/rpl.rpl_innodb_bug28430'
 - found 'core' (0/5)

Trying 'dbx' to get a backtrace
Core generated by '/export/home/pb2/test/sb_6-630897-1247001400.61/mysql-5.1.37-solaris10-i386-test/bin/mysqltest'
Output from dbx follows. Stack trace is printed for all threads in order,
above this you should see info about which thread was the failing one.
----------------------------
For information about new features see `help changes'
To remove this message, put `dbxenv suppress_startup_message 7.6' in your .dbxrc
Reading mysqltest
core file header read successfully
Reading ld.so.1
Reading libpthread.so.1
Reading libthread.so.1
Reading libstdc++.so.6.0.3
Reading libgcc_s.so.1
Reading librt.so.1
Reading libsocket.so.1
Reading libnsl.so.1
Reading libm.so.2
Reading libc.so.1
Reading libm.so.1
Reading libaio.so.1
Reading libmd.so.1
t@1 (l@1) program terminated by signal ABRT (Abort)
0xfecf53a5: __lwp_kill+0x0015:	jae      __lwp_kill+0x23	[ 0xfecf53b3, .+0xe ]
Current function is my_write_core
dbx: warning: can't find file "/export/home/pb2/build/sb_0-630652-1246996941.85/mysql-5.1.37/mysys/stacktrace.c"
dbx: warning: see `help finding-files'
current thread: t@1

How to repeat:
run the test for bug #28430 on a solaris host enough times

Suggested fix:
n/a
[8 Jul 2009 7:33] 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/78181

3013 Georgi Kodinov	2009-07-08
      Bug#38998, Bug#46029, Bug#45243, Bug#46030 making tests experimental
[8 Jul 2009 13:30] Bugs System
Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:joro@sun.com-20090708073149-qxyfa5vkh1m0pvol) (merge vers: 5.1.37) (pib:11)
[9 Jul 2009 7:36] Bugs System
Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:joro@sun.com-20090708073149-qxyfa5vkh1m0pvol) (merge vers: 5.1.37) (pib:11)
[10 Jul 2009 11:20] Bugs System
Pushed into 5.4.4-alpha (revid:anozdrin@bk-internal.mysql.com-20090710111017-bnh2cau84ug1hvei) (version source revid:joro@sun.com-20090708121727-rekm6n1iu4vmvcfa) (merge vers: 5.4.4-alpha) (pib:11)
[26 Aug 2009 13:45] Bugs System
Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[26 Aug 2009 13:46] Bugs System
Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)
[26 Aug 2009 13:48] Bugs System
Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)
[27 Aug 2009 16:32] Bugs System
Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[27 Oct 2010 10:30] Sven Sandberg
Just an update to say that this still fails in 5.5 (e.g. 2010-10-11), and that there are stack traces at http://tinyurl.com/2uheq57
[7 Jan 2011 11:41] Alfranio Junior
This is not a sporadic failure in my box:

  . x86 64 bit
  . 2.6.35-24-generic #42-Ubuntu SMP 
  . gcc (Ubuntu/Linaro 4.4.4-14ubuntu5) 4.4.5
[14 Jan 2011 18:36] Mikael Ronström
Also a not sporadic failure in my box (as long as I run
with e.g. parallel=3 and e.g. with command:
perl mysql-test-run.pl --suite=rpl --do-test=rpl_innodb --parallel=3

It times out after 900 secs.

I have a six-core x86 box with Fedora Core 12 to reproduce this.
[30 Jan 2013 18:38] Sveta Smirnova
Bug #65518 was marked as duplicate of this one.
[11 Mar 2014 7:26] Erlend Dahl
We don't see this in our internal testing any more, so closing as "can't repeat".
[23 Apr 2018 17:23] Valeriy Kravchuk
This test still fails for me on quadcore Fedora 27 and 2-core Ubuntu 14.04 netbook with vewrsion 8.0.11 built from GitHub source code:

[openxs@fc23 mysql-test]$ ./mtr rpl.rpl_innodb_bug28430
Logging: ./mtr  rpl.rpl_innodb_bug28430
2018-04-23T16:51:01.157882Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161)
2018-04-23T16:51:01.158009Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000)
2018-04-23T16:51:01.158400Z 0 [System] [MY-010116] [Server] /home/openxs/dbs/8.0/bin/mysqld (mysqld 8.0.11) starting as process 3325
MySQL Version 8.0.11
Checking supported features...
 - SSL connections supported
Collecting tests...
 - adding combinations for rpl
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/8.0/mysql-test/var'...
Installing system database...
Using parallel: 1

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

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

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_innodb_bug28430 'mix'            [ pass ]  872376
worker[1] Trying to dump core for [mysqltest - pid: 3572, winpid: 3572]
worker[1] Trying to dump core for [mysqld.1 - pid: 3498, winpid: 3498]
worker[1] Trying to dump core for [mysqld.2 - pid: 3500, winpid: 3500]
rpl.rpl_innodb_bug28430 'row'            [ fail ]  timeout after 900 seconds
        Test ended at 2018-04-23 20:22:28

Test case timeout after 900 seconds

== /home/openxs/dbs/8.0/mysql-test/var/log/rpl_innodb_bug28430.log ==
INSERT INTO test.byrange_tbl VALUES (NULL, NOW(), USER(), UUID(),
ins_count,'Going to test MBR for MySQL');
SET ins_count = ins_count - 1;
END WHILE;
SELECT MAX(id) FROM test.byrange_tbl INTO del_count;
WHILE del_count > 0 DO
DELETE FROM test.byrange_tbl WHERE id = del_count;
SET del_count = del_count - 2;
END WHILE;
END|
CALL test.proc_norm();
SELECT count(*) as "Master regular" FROM test.regular_tbl;
Master regular  500
CALL test.proc_bykey();
SELECT count(*) as "Master bykey" FROM test.bykey_tbl;
Master bykey    500
CALL test.proc_byrange();
SELECT count(*) as "Master byrange" FROM test.byrange_tbl;
Master byrange  500
include/sync_slave_sql_with_master.inc

 == /home/openxs/dbs/8.0/mysql-test/var/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/home/openxs/dbs/8.0/mysql-test/var/tmp/mysqld.1.sock' (111)
safe_process[3664]: Child process: 3665, exit: 1

 == /home/openxs/dbs/8.0/mysql-test/var/tmp/analyze-timeout-mysqld.2.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/home/openxs/dbs/8.0/mysql-test/var/tmp/mysqld.2.sock' (111)
safe_process[3666]: Child process: 3667, exit: 1

 - the logfile can be found in '/home/openxs/dbs/8.0/mysql-test/var/log/rpl.rpl_innodb_bug28430-row/rpl_innodb_bug28430.log'

Only  2  of 3 completed.
mysql-test-run: *** ERROR: Not all tests completed