Bug #42189 falcon.falcon_bug_22211 fails due to blocked transaction sees rollbacked data
Submitted: 18 Jan 2009 22:05 Modified: 15 May 2009 15:49
Reporter: Olav Sandstå Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0.10-alpha OS:Any
Assigned to: Olav Sandstå
Tags: F_TRANSACTION
Triage: Triaged: D2 (Serious)

[18 Jan 2009 22:05] Olav Sandstå
Description:
While trying to reproduce Bug#41391, test falcon_bug_22211 fails on the second test case when testing that a blocked transaction is alloweded to proceed if the blocking transaction is roll-backed to last savepoint. The error from the test is:

mysqltest: At line 102: query 'reap' failed: 1062: Duplicate entry '100' for key
 'PRIMARY'

The result from queries just before the failure was:
< snip >
SELECT * FROM t1;
a
100
# Switch to connection 1 (REPEATABLE READ)
START TRANSACTION;
SELECT * FROM t1;
a
0
# send INSERT (100) - This should SUCCEED after 100 is rolled back.
INSERT INTO t1 VALUES(100);;
# Switch to connection default (REPEATABLE READ)
# Rollback the value 100
ROLLBACK TO SAVEPOINT sp1;
# Commit the value 10
COMMIT;
SELECT * FROM t1;
a
10
# Switch to connection 1 (REPEATABLE READ)
# reap - INSERT (100)

This might be the same cause as for Bug#41391 or a different error.

How to repeat:
Re-run test falcon_bug_22211 "a few times" - this crash happened on re-run number 71507 of the test.

Suggested fix:
A transaction blocked due to waiting for second transaction that have inserted the same record should not see the data of the second transaction if the second transaction does a rollback to save-point.
[19 Jan 2009 14:24] Olav Sandstå
Hi Miguel, Sorry for not including branch information:

The source code I use was checked out from the mysql-6.0-falcon-team tree on Friday January 16th and have revision number 2963.
[20 Jan 2009 22:08] Godofredo Miguel Solorzano
Thank you for the feedback. I tried several times and I couldn't repeat with latest source tree, could you please test again. I ran the test on 64-bit Suse 11.1:

Installing Master Database
Saving snapshot of installed databases
=======================================================

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

falcon.falcon_bug_22211        [ pass ]            104
falcon.falcon_bug_22211        [ pass ]            110
falcon.falcon_bug_22211        [ pass ]             96
falcon.falcon_bug_22211        [ pass ]            141
falcon.falcon_bug_22211        [ pass ]            117
falcon.falcon_bug_22211        [ pass ]            112
falcon.falcon_bug_22211        [ pass ]             95
falcon.falcon_bug_22211        [ pass ]             96
falcon.falcon_bug_22211        [ pass ]            109
falcon.falcon_bug_22211        [ pass ]            106
falcon.falcon_bug_22211        [ pass ]            132
falcon.falcon_bug_22211        [ pass ]            123
falcon.falcon_bug_22211        [ pass ]            109
falcon.falcon_bug_22211        [ pass ]            105
falcon.falcon_bug_22211        [ pass ]            115
falcon.falcon_bug_22211        [ pass ]            160
falcon.falcon_bug_22211        [ pass ]            111
falcon.falcon_bug_22211        [ pass ]            110
falcon.falcon_bug_22211        [ pass ]             99
falcon.falcon_bug_22211        [ pass ]             96
falcon.falcon_bug_22211        [ pass ]             97
falcon.falcon_bug_22211        [ pass ]             98
falcon.falcon_bug_22211        [ pass ]            104
falcon.falcon_bug_22211        [ pass ]             97
falcon.falcon_bug_22211        [ pass ]            115
falcon.falcon_bug_22211        [ pass ]            111
falcon.falcon_bug_22211        [ pass ]            109
falcon.falcon_bug_22211        [ pass ]            112
falcon.falcon_bug_22211        [ pass ]            117
falcon.falcon_bug_22211        [ pass ]            137
falcon.falcon_bug_22211        [ pass ]            172
falcon.falcon_bug_22211        [ pass ]            138
falcon.falcon_bug_22211        [ pass ]            116
falcon.falcon_bug_22211        [ pass ]             98
falcon.falcon_bug_22211        [ pass ]            100
falcon.falcon_bug_22211        [ pass ]            107
-------------------------------------------------------
Stopping All Servers
All 36 tests were successful.
[20 Jan 2009 22:24] Olav Sandstå
Hi, I am not sure how easy it is to reproduce this crash. As I mentioned in the initial bug report the crash happened on re-run number 71507 of this test - and I have only seen the crash once,

When I got it I ran the debug-build of MySQL on a dual CPU AMD server running Solaris 10 MU5.
[21 Jan 2009 13:57] Olav Sandstå
Setting this to Analysing until I have been able to reproduce it.
[9 Mar 2009 8:24] Olav Sandstå
Setting this to verified based on that I have been able to reproduce it by running this test 184052 times using the latest sources from the mysql-6.0-falcon-team tree.
[9 Mar 2009 9:05] Kevin Lewis
To my surprise, I found that there is NO sleep after the
--send INSERT INTO t1 VALUES(10);
Please add a --real_sleep 1 after the --send and before 
the following ROLLBACK.

--send INSERT INTO t1 VALUES(10);
--echo # Switch to connection default (REPEATABLE READ)
connection default;
--echo # Rollback the value 100
--real_sleep 1   <-- Add this and try to recreate
ROLLBACK TO SAVEPOINT sp1;
--echo # Commit the value 10
COMMIT;
[15 Apr 2009 18:10] Olav Sandstå
This bug seems to have been fixed by the new Cycle Manager and the new Transaction State object that was introduced into Falcon about a month ago. I have re-run the test 484.000 times without seeing any crashes.
[15 Apr 2009 18:10] Olav Sandstå
Fix is in 6.0.11
[15 May 2009 15:49] MC Brown
An entry has been added to the 6.0.11 changelog: 

The Falcon CycleManager has been updated, which addresses a number of issues when examining records in various transaction states and their visisbility/isolation in relation to other threads.