Bug #53625 Deadlock with log_output=TABLE, partitioned table, trigger and auto-inc
Submitted: 13 May 2010 17:46 Modified: 4 Feb 2011 16:17
Reporter: Elena Stepanova Email Updates:
Status: Won't fix Impact on me:
Category:MySQL Server: Locking Severity:S2 (Serious)
Version:5.1.49, 5.5.3-m3, 5.6.99 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D1 (Critical)

[13 May 2010 17:46] Elena Stepanova
- Table tb1_eng1 has AUTO_INCREMENT PK i1 and is partitioned by hash(i1);
- Tables tb1_logs and t1 do not have indexes, partitions, AUTO_INCREMENTs;
- Tables tb1_eng1 and tb1_logs are empty at start, table t1 contains 1 row;
- Trigger after insert on tb1_eng1 writes into tb1_logs.

- several connections execute concurrently the following statement:
INSERT INTO systest1.tb1_eng1 (f1,f2,f3,f4)
SELECT f1, f2, f3, f4
FROM systest1.t1;

If log_output is set to TABLE and STATEMENT-based or MIXED binary log format is used, the flow deadlocks soon after it starts.

Reproducible with InnoDB and MyISAM tables.
Also reproducible on 5.1.40sp1.

In the provided test case, I could not exclude partitions, SBR/MBR, auto-increment and trigger, so am not quite if it belongs to 'Locking', but setting the category to it for now.

How to repeat:
- unpack the attached archive in <mysql-basedir>/mysql-test. It should create
'stress_test_basedir' folder;
- run as
perl ./stress_test_basedir/run.pl

run.pl is a wrapper for MTR to start server, and mysql-stress-test
to run a multi-thread stress test.
For mysql-stress-test you need to have perl with threads on the top of your path

Please use 
perl ./stress_test_basedir/run.pl --help 
for the list of available options (if default configuration is not suitable for you).

STDOUT should contain usual MTR output for server startup
(unless you chose to skip server start), then it will briefly go through
preparation/initialization/configuration stages marked accordingly,
and then will start rapidly producing lines like

test_loop[0:0 0:84]: TID 5 test: 'stress1'  Errors: No Errors. Test Passed OK

test_loop[0:0 0:85]: TID 4 test: 'stress1'  Errors: No Errors. Test Passed OK

main: Thread ID 6 TID 6 started
test_loop[0:0 0:86]: TID 3 test: 'stress1'  Errors: No Errors. Test Passed OK


If the deadlock is reached, the output stops.
Usually it happens during the first minute of the first attempt, but sometimes it takes 2 or 3 test runs.

If deadlock does not happen, the test finishes in 2 min saying 
[13 May 2010 17:48] Elena Stepanova
bt for all threads

Attachment: 53625_threads.out (application/octet-stream, text), 27.33 KiB.

[13 May 2010 17:48] Elena Stepanova
bt full for all threads

Attachment: 53625_threads_full.out (application/octet-stream, text), 89.33 KiB.

[13 May 2010 17:49] Elena Stepanova
mysql-stress-test-based test

Attachment: 53625_stress_test_basedir.tar.gz (application/gzip, text), 14.38 KiB.

[14 May 2010 6:47] Marc Alff

starting with 5.5, the performance schema can also provide details about the dead lock.
Have you tried to see:
- what each thread waits for (SELECT * from EVENTS_WAITS_CURRENT)
- who locks each mutex (SELECT * from MUTEX_INSTANCES)
from another connection ?

This will help to narrow down the bug.
[14 May 2010 8:51] Elena Stepanova
Hi Marc,

The problem is that as soon as the deadlock happens, I cannot connect to the server anymore, and if I already have a connection, I cannot execute a query, including those from P_S.
[14 May 2010 9:11] Elena Stepanova
Another note on versions:
with the provided test case, I get the deadlock regularly on 5.5.3-m3 and current 5.5.5, but could not reproduce it so far on 5.5.4-m3.
[14 May 2010 11:19] Philip Stoev
Not being able to connect and not being able to issue commands is typical for deadlocks where log_output=TABLE, because the log table gets locked out too. The solution is to connect the client before the deadlock has formed and issue SET SESSION log_output=file . SHOW PROCESSLIST and selecting from PERFORMANCE SCHEMA should then work.
[14 May 2010 11:35] Elena Stepanova
I thought about it before, but the manual (http://dev.mysql.com/doc/refman/5.5/en/server-options.html#option_mysqld_log-output) says that the scope of log_output variable is only global, so I did not try. I can still check it out if there is a suspicion it can be set on session level.
[12 Jul 2010 18:28] Elena Stepanova
Could not reproduce it on the final version of 5.5.5-m3 -- there have been some changes in the area (e.g. WL#5419, bug#50589, etc.), apparently the problem was along with them; not closing it though because it is still easily reproducible on current 5.1.
[4 Feb 2011 16:18] Omer Barnir
Issue is addressed in 5.5