Bug #41478 Falcon transactions see uncommited updates

Description:
When executing a concurrent workload, Falcon SELECT queries see an inconsistent view of the database.

This issue happens even if all transactions are rollbacked, regardless of the transaction isolation level and regardless of the --falcon-consistent-read option.

How to repeat:
clone the mysql-test-extra-6.0 tree and then execute:

$ cd mysql-test/gentest

$ perl runall.pl \
  --basedir=/build/bzr/6.0-falcon-team \
  --engine=Falcon \
  --gendata=conf/transactions.zz \
  --grammar=conf/transactions.yy \
  --validator=DatabaseConsistency \
  --queries=100000

This will create a table with 10 records and will then proceed to run random queries which do not change the total sum of all values in the table. After each query, the sum will be checked and if the database deviates from the consistent state, the test will fail with an error.

All that is needed is a concurrent workload that executes the following fully-formed, non-deadlocking rollbacked transaction:

                   17 Query     START TRANSACTION
                   17 Query     INSERT INTO `table10_falcon_int_autoinc` ( `pk` , `int_key` , `int` ) VALUES ( NULL , 123 , 234 )
                   17 Query     DELETE FROM `table10_falcon_int_autoinc` WHERE `pk` = @@LAST_INSERT_ID
                   17 Query     ROLLBACK

A SELECT running concurrently with those queries will sometimes see the row being inserted even though the entire transaction is always rolled back.

This happens even with --falcon-consistent-read=1 and REPEATABLE READ transactions.

Kevin wrote,
Philip, This seems to be working for me now. Is it working for you?

perl runall.pl \
  --basedir=/build/bzr/6.0-falcon-team \
  --engine=Falcon \
  --gendata=conf/transactions.zz \
  --grammar=conf/transactions.yy \
  --validator=DatabaseConsistency \
  --queries=100000 

Philip wrote;  
Kevin, After Hakan's latest merge, this test no longer fails in the way described and this bug is no longer reproducible. I have no idea why.

Grammar file for bug 41478

Attachment: bug41478.yy (application/octet-stream, text), 1.47 KiB.

To reproduce:

$ perl runall.pl \
  --basedir=/build/bzr/6.0-falcon-team \
  --engine=Falcon \
  --grammar=conf/bug41478.yy \
  --gendata=conf/transactions.zz \
  --validator=DatabaseConsistency \
  --mysqld=--falcon-consistent-read=1 \
  --queries=100000

I was finally able to reproduce this problem;
# 23:22:29 Query: SELECT `int_key` FROM `table10_falcon_int_autoinc` WHERE 1 = 1 returns different result when executed with additional predicate 'AND
 `pk` > -16777216' (21 vs. 22 rows).
# 23:22:29 Query: SELECT `pk` FROM `table10_falcon_int_autoinc` WHERE 1 = 1 returns different result when executed with additional predicate 'AND `pk`
 > -16777216' (35 vs. 36 rows).
# 23:22:29 Query: SELECT `int` FROM `table10_falcon_int_autoinc` WHERE 1 = 1 returns different result when executed with additional predicate 'AND `pk
` > -16777216' (28 vs. 29 rows).
# 23:22:29 Query: SELECT `int` FROM `table10_falcon_int_autoinc` WHERE 1 = 1 returns different result when executed with additional predicate 'AND `pk
` > -16777216' (23 vs. 24 rows).

Kevin, I think your last comment pertains to bug #41742

To reproduce:

$ perl runall.pl \
  --basedir=/build/bzr/6.0-falcon-team \
  --engine=Falcon \
  --grammar=conf/bug41478.yy \
  --gendata=conf/transactions.zz \
  --validator=DatabaseConsistency \
  --mysqld=--falcon-consistent-read=1 \
  --queries=100000 \
  --mem \
  --mysqld=--log-output=file \
  --threads=3

This will result in an error such as:

# 11:42:26 Bad average for table: table10_falcon_int_autoinc; average1: 191.8182; average2: 191.8182; count: 11; affected_rows: 0E0; query: START TRANSACTION

Note the count: 11 . This means that the table contained 11 rows, even though the SQL grammar will never commit a new row. The table should have 10 rows only - all inserted rows are immediately deleted and should never be visible to other connections.

Debugged by Jim Starkey:

Found it with Philips Database Colonoscopy Program (PDC). To trap the problem, I added the following code to StorageTable::next():

int ret = storageDatabase->nextRow(this, recordNumber, lockForUpdate);

if (ret >= 0)
    {
    if (historyIndex >= recordHistorySize)
        Log::debug("history overflow\n");
    else
        {
        RecordHistory *history = recordHistory + historyIndex++;
        history->record = record;
        history->recordNumber = record->recordNumber;
        history->transaction = record->getTransaction();
        history->transactionId = record->getTransactionId();
        }
    }

15 seconds later I had a snapshot of the bug.

The problem is in Tranasction::removeRecord called from RecordVersion::scavengeSavepoint. Transaction::removeRecord zaps the transaction pointer while the record is still visible to other threads, making it appear to be fully committed.

Per Jim: 

The fix is to remove the line

    record->transaction = NULL;

from Transaction::removeRecordNoLock(RecordVersion *record).

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

3067 Christopher Powers	2009-03-19
      Bug #41478, "Falcon transactions see uncommited updates"
      
      When removing a record from a transaction, leave RecordVersion::transaction
      to ensure that the record does not appear to be fully committed and therefore
      visible to other transactions.

For the record, this (or a similar) issue has also been observed (only once so far) during transactional mysql-stress-test test suite "stress_tx_rr", using revision hky@sun.com-20090310135113-i36spde1f6duc5xn (mysql-6.0-falcon-team as of March 10). 

An uncommitted (later rolled back) record was seen by a different REPEATABLE-READ transaction during a test run with 50 concurrent threads on a 4-CPU machine. This was a transient occurrence which did not repeat later in the test run. Seen in one of three 2-hour test runs so far.

 START TRANSACTION;
 SELECT * FROM t1 WHERE `is_uncommitted` > 0;
 pk     id      int1    int1_key        int1_unique     int2    int2_key        int2_unique     for_update      timestamp       connection_id   thread_id
       is_uncommitted  is_consistent
+514    50      50      1050    514     -1050   -1000   -514    0       2009-03-21 12:53:48     10112   0       1       0
 COMMIT;

Jim's fix that Chris committed caused an exception when trying to create falcon tablespaces on startup:

090319 18:34:18 [Note] Falcon: unable to open system data files.
090319 18:34:18 [Note] Falcon: creating new system data files.
090319 18:34:19 [ERROR] Falcon: create database failed : update conflict in 
table SYSTEM.TABLES record 4
prior open database failure was: can't open file 
"/tmp/datadir/falcon_master.fts": No such file or directory (2)
090319 18:34:19 [ERROR] Plugin 'Falcon' init function returned error.
090319 18:34:19 [ERROR] Plugin 'Falcon' registration as a STORAGE ENGINE 
failed.

>	mysqld.exe!Table::validateAndInsert(Transaction * 
transaction=0x03ef87d0, RecordVersion * record=0x0661b350)  Line 3371	C++
  	mysqld.exe!Table::update(Transaction * transaction=0x03ef87d0, Record
* oldRecord=0x06612600, int numberFields=1, Nfs::Field * *
updateFields=0x03ee0b18, Value * * values=0x03ee2840)  Line 1381	C++
  	mysqld.exe!NUpdate::evalStatement(Nfs::Statement *
statement=0x03ed40d0)  Line 144	C++
  	mysqld.exe!Nfs::Statement::start(NNode * node=0x03ee25e8)  Line 492
+ 0x11	C++
  	mysqld.exe!PreparedStatement::executeUpdate()  Line 87	C++
  	mysqld.exe!Table::reformat()  Line 477 + 0xd	C++
  	mysqld.exe!Nfs::Statement::upgradeTable(Syntax * syntax=0x03ef63e8)
Line 1382	C++
  	mysqld.exe!Nfs::Statement::executeDDL()  Line 745	C++
  	mysqld.exe!Nfs::Statement::execute(const char * sqlString=0x00d4aaa0,
bool isQuery=false)  Line 2727	C++
  	mysqld.exe!Nfs::Statement::execute(const char * sqlString=0x00d4aaa0)
  Line 163	C++
  	mysqld.exe!Database::upgradeSystemTables()  Line 2079 + 0x13	C++
  	mysqld.exe!Database::createDatabase(const char * filename=0x0012de08)
  Line 703	C++
  	mysqld.exe!Connection::createDatabase(const char * dbName=0x03ed026c,
const char * fileName=0x03ed029c, const char * account=0x00d45d2c, const
char * password=0x00d45d24, Threads * threads=0x03ed02c8)  Line 1063 +
0x1a	C++
  	mysqld.exe!StorageDatabase::createDatabase()  Line 163	C++
  	mysqld.exe!StorageHandler::createDatabase()  Line 1027	C++
  	mysqld.exe!StorageHandler::initialize()  Line 1004 + 0x8	C++
  	mysqld.exe!StorageInterface::falcon_init(void * p=0x02719368)  Line
262 + 0xb	C++
  	mysqld.exe!ha_initialize_handlerton(st_plugin_int *
plugin=0x01631248)  Line 448 + 0x1b	C++
  	mysqld.exe!plugin_initialize(st_plugin_int * plugin=0x01631248)  Line
1008 + 0x15	C++
  	mysqld.exe!plugin_init(int * argc=0x00f95cbc, char * *
argv=0x015a85c0, int flags=2)  Line 1220 + 0x9	C++
  	mysqld.exe!init_server_components()  Line 4078 + 0x2f	C++
  	mysqld.exe!win_main(int argc=31, char * * argv=0x015a3a30)  Line
4589 + 0x5	C++
  	mysqld.exe!mysql_service(void * p=0x00000000)  Line 4752 + 0x12	C++
  	mysqld.exe!main(int argc=31, char * * argv=0x015a3a30)  Line 4925 +
0x7	C++
  	mysqld.exe!mainCRTStartup()  Line 259 + 0x19	C

Also for the record:
The proposed fix did not work. It resulted in an error on startup, so it was reverted. That is why this bug is still In progress.

Philip reported that this problem cannot be repeated after the changes to create a
TransactionState object and the addition of the CycleManager to protect doomed records until after all temporary stack pointers to them have gone away.

A note have 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.