MySQL Bugs: #38172: rpl_locktrans_innodb times out sporadically on pushbuild

Bug #38172	rpl_locktrans_innodb times out sporadically on pushbuild
Submitted:	16 Jul 2008 13:55	Modified:	23 Jul 2010 9:29
Reporter:	Sven Sandberg	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	Tests: Replication	Severity:	S7 (Test Cases)
Version:	6.0	OS:	Any
Assigned to:	Sven Sandberg	CPU Architecture:	Any
Tags:	pushbuild, rpl_locktrans_innodb, sporadic, test failure, timeout

Description:
rpl_locktrans_innodb fails with the following message:

rpl.rpl_locktrans_innodb 'stmt' [ fail ]  timeout

Stopping All Servers

How to repeat:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0&order=27 powermacg5/ps_stm

xref: http://tinyurl.com/675ny8

All failures seen so far were on powermacgv/ps_stm. I believe that host is known to be slow, so one may suspect that the test case merely took a long time.

Suggested fix:
Timeout errors are almost impossible to debug, since no debug information is given.

I'd suggest augmenting mtr so that it forces a stop of the test case, outputs a result diff, outputs the result of "SHOW PROCESSLIST" on all running servers (that can indicate if the servers are overloaded), and outputs the time that mtr waited before timeout.

Recent occurrences on PB2
=========================

  Sample 1
  ========

http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2321633

rpl.rpl_locktrans_innodb                 w6 [ fail ]  timeout after 900 seconds
        Test ended at 2009-09-14 20:14:07

Test case timeout after 900 seconds

== /export/home/pb2/test/sb_1-745119-1252949708.16/mysql-5.4.4-alpha-solaris10-sparc-test/mysql-test/var/6/log/rpl_locktrans_innodb.log == 
COMMIT;
#
# LOW_PRIORITY WRITE behaves like WRITE in transaction mode.
# Insert a value.
INSERT INTO t1 VALUES(111);
COMMIT;
# Take a non-transactional lock.
LOCK TABLE t1 READ;
# connection conn1.
# Take a non-transactional LOW_PRIORITY WRITE lock,
# which waits in background until first read lock is released.
LOCK TABLE t1 LOW_PRIORITY WRITE;
# connection default.
# Wait for the helper thread to sit on its lock.
# connection conn2.
# Take a non-transactional READ lock,
# which waits in background for the LOW_PRIORITY WRITE lock.
LOCK TABLE t1 READ;
# connection default.
# Wait for the helper threads to sit on their locks.

  Sample 2
  ========

rpl.rpl_locktrans_innodb                 w4 [ fail ]
        Test ended at 2009-09-08 13:08:02

CURRENT_TEST: rpl.rpl_locktrans_innodb
mysqltest: In included file "./include/locktrans.inc": At line 691: query 'reap' failed: 1205: Lock wait timeout exceeded; try restarting transaction

The result from queries just before the failure was:
< snip >
INSERT INTO t1 VALUES(111);
COMMIT;
# Take a non-transactional lock.
LOCK TABLE t1 READ;
# connection conn1.
# Take a non-transactional LOW_PRIORITY WRITE lock,
# which waits in background until first read lock is released.
LOCK TABLE t1 LOW_PRIORITY WRITE;
# connection default.
# Wait for the helper thread to sit on its lock.
# connection conn2.
# Take a non-transactional READ lock,
# which waits in background for the LOW_PRIORITY WRITE lock.
LOCK TABLE t1 READ;
# connection default.
# Wait for the helper threads to sit on their locks.
# Unlock this connections non-transactional lock.
UNLOCK TABLES;
# connection conn1.
# Now the LOW_PRIORITY WRITE lock is taken.