MySQL Bugs: #55426: mysqltest crashes when trying to unlock not acquired mutex

Bug #55426	mysqltest crashes when trying to unlock not acquired mutex
Submitted:	21 Jul 2010 7:01	Modified:	14 Nov 2010 2:53
Reporter:	Alexander Nozdrin	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Tools: MTR / mysql-test-run	Severity:	S7 (Test Cases)
Version:	M3 (Celosia), M4 (Dahlia)	OS:	Any
Assigned to:	Bjørn Munch	CPU Architecture:	Any
Tags:	pb2, sporadic, test failure

Description:
From time to time mysqltest crashes while trying to unlock mutex
that wasn't locked.

Symptoms:
------------------------------------------------------------
main.lock_multi_bug38499 [ fail ]
        Test ended at 2010-07-21 02:17:10

CURRENT_TEST: main.lock_multi_bug38499
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
100721  3:17:09  InnoDB: highest supported file format is Barracuda.
safe_mutex: Trying to unlock mutex that wasn't locked at /export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/client/mysqltest.cc, line 722
            Last used at /export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/client/mysqltest.cc, line: 735
mysqltest got signal 6
read_command_buf at 0x15791e0 = }
conn->name at 0x1adbf6e0 = locker
conn->cur_query at (nil) is an invalid pointer
Attempting backtrace...
stack_bottom = (nil) thread_stack 0x40000
/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/libmysqld/examples/mysqltest_embedded(my_print_stacktrace+0x44)[0x56b168]
/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/libmysqld/examples/mysqltest_embedded[0x511edf]
/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/libmysqld/examples/mysqltest_embedded[0x511f41]
/lib64/libpthread.so.0[0x33eda0de70]
/lib64/libc.so.6(gsignal+0x35)[0x33ece30155]
/lib64/libc.so.6(abort+0x110)[0x33ece31bf0]
/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/libmysqld/examples/mysqltest_embedded(safe_mutex_unlock+0xe9)[0x5648c8]
/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/libmysqld/examples/mysqltest_embedded(send_one_query+0x102)[0x52ca08]
/lib64/libpthread.so.0[0x33eda062f7]
/lib64/libc.so.6(clone+0x6d)[0x33eced1b6d]
Writing a core file...

 - saving '/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/mysql-test/var/log/main.lock_multi_bug38499/' to '/export/home2/pb2/build/sb_1-None-1279652440.51/mysql-trunk-bugfixing-gcov/mysql-test/var/log/main.lock_multi_bug38499/'

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

main.lock_multi_bug38499                 [ retry-pass ]   2430

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

main.lock_multi_bug38499                 [ retry-pass ]   2210
------------------------------------------------------------

How to repeat:
XRef:
  - http://tinyurl.com/37xns4h
  - http://tinyurl.com/3yhfaqa (might represent failures not related to this bug)

Thank you for the report.

Verified using pushbuild logs.

The links are broken and sends me on to some strange login page. And because it's hidden in tinyurl I cannot see what it really is.

Does this happen only in the gcov runs?

They are not broken, they just use VPN/HTTP :)

Links:

http://pb2.norway.sun.com/?template=mysql_show_test_failure&test_failure_id=&test_output_i...

http://pb2.norway.sun.com/?template=mysql_show_test_failure&test_failure_id=&test_output_i...

I've found a possible race condition in thread scheduling, in my first success at reproducing the crash it happened on the order of 1 in 250,000 iterations of a test loop doing send/reap commands. Seems to happen on Linux only. Now trying to reproduce again to validate a fix....

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/118146

3087 Bjorn Munch	2010-09-14
      Bug #55426 mysqltest crashes when trying to unlock not acquired mutex
      Bug #55546 mysqltest fails to create a new thread on HPUX
      Missing call to pthread_join(), in embedded mode
      This independently solves both problems, see 55426 for details.

This may happen with send/reap. A new thread is started to do the query, this locks the mutex and then calls pthread_cond_signal(). If the main thread in the meantime has continued processing and reached the reap command, it will be blocked on pthread_cond_wait(). It will then wake up and start processing.

If this is in a loop, it may continue holding the CPU until it reaches the next iteration and another send. This kicks off another query thread on the *same* channel, which will start doing its work.

Only then is the first query thread re-scheduled after pthread_cond_signal() and the first thing it tries to do is to unlock the mutex, which by this time has been re-initialized by the other thread. BOOM!

I was able to reproduce this on a linux box by executing this test with repetitions:

--------------------------
connect (c1,localhost,root,,);
connect (c2,localhost,root,,);

--disable_query_log
--disable_result_log
let $i = 10000;

while ($i) {
--dec $i

--connection c1
  send select 1 as a;
--connection c2
  select 2 as b;
  select 3 as c;
--connection c1
  reap;
}
-------------------------

It would fail about once every 1,000,000 iterations of the loop. But later I could see it happen 10x more frequently on a supposedly identical box.

After the fix, not only doesn't it fail, it runs about 3x faster. So it seems clear that the "zombie" threads are also eating resources.

The extra test for tid !=0 is to prevent crash in clean-up with connections that have not been used.

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/118189

2930 Bjorn Munch	2010-09-14
      Bug #55426 mysqltest crashes when trying to unlock not acquired mutex
      Bug #55546 mysqltest fails to create a new thread on HPUX
      Missing call to pthread_join(), in embedded mode
      This independently solves both problems, see 55426 for details.

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/118196

2930 Bjorn Munch	2010-09-14
      Bug #55426 mysqltest crashes when trying to unlock not acquired mutex
      Bug #55546 mysqltest fails to create a new thread on HPUX
      Missing call to pthread_join(), in embedded mode
      This independently solves both problems, see 55426 for details.
      Addendum: cannot test against a pthread_t, adds boolean flag instead

Pushed to -mtr branches

A few tests time out in 5.1-mtr on Windows, this seems to be caused by the 5.1 macro for pthread_join() hanging indefinitely when the thread has already exited, at least in some cases. See also Bug #26564.

I'm inclined to just #ifndef it away on Windows, since the problem it solves has not been observed there and it's not a problem on 5.5.

Yes, was about to warn you about that pthread_join is not implemented on Windows in 5.1(it is implemented in 5.5 though). (please check code to evrify my statement) :)

Ok to ifdef away on Windows in 5.1, but check if it works or not in 5.5 first.

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/118576

2932 Bjorn Munch	2010-09-20
      Bug #55426 mysqltest crashes when trying to unlock not acquired mutex
      Follow-up: don't call pthread_join() on Windows
      This change only valid for 5.1

Changes to test suite. No changelog entry needed.

Pushed into mysql-5.1 5.1.53 (revid:build@mysql.com-20101101184443-o2olipi8vkaxzsqk) (version source revid:build@mysql.com-20101101184443-o2olipi8vkaxzsqk) (merge vers: 5.1.53) (pib:21)

Pushed into mysql-5.5 5.5.7-rc (revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (version source revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (merge vers: 5.5.7-rc) (pib:21)

Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:alexander.nozdrin@oracle.com-20101113152450-2zzcm50e7i4j35v7) (merge vers: 5.6.1-m4) (pib:21)

Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (pib:21)