Bug #43091 Statements in transactions skipped
Submitted: 22 Feb 2009 16:38 Modified: 24 Feb 2009 8:57
Reporter: Omer Barnir (OCA) Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.0.77, 5.1.31, 6.0.9 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D1 (Critical)

[22 Feb 2009 16:38] Omer Barnir
Description:
When two update statements as part of a transaction in the form of 

START TRANSACTION;
   SET @randpk=FLOOR(0 + (RAND() * 10));
   UPDATE `table10_innodb_int_autoinc` SET `int`=`int`-10 WHERE pk=@randpk;
   SET @randpk=FLOOR(0 + (RAND() * 10));
   UPDATE `table10_innodb_int_autoinc` SET `int`=`int`+10 WHERE pk=@randpk;
COMMIT;

some of the UPDATE statements are skipped for some of the transactions (i.e. some of the transactions performs only one of the two UPDATE statements.

This is observed when running with a single user (no concurrency)

Problem not observed if adding a 'select sleep(1)' between the two updates.

How to repeat:
Start the server using mysql-test-run.pl --start-and-exit --mysqld=--innodb (replication is optional if you want to see the transaction not going into the binlog, but niot a must)

Execute the attached trans_fail.sql file using the client:
mysql --user=root --protocol=tcp --port=9306 < trans_fail.sql

Notes
The script includes sleep(1) statements between the transactions. These are put there simply to have a clearer separation between the updates of each transaction.

The trigger is included in order to demonstrate the problem, the failures show even when the trigger is commented out.

Output (omitting sleeps): 
+----+------+
| pk | int  |
+----+------+
|  1 |  120 |
|  2 |  100 |
|  3 |  110 |
|  4 |  100 |
|  5 |  110 |
|  6 |   90 |
|  7 |   70 |
|  8 |  110 |
|  9 |   80 |
| 10 |  100 |
+----+------+
+------------+
| avg(`int`) |
+------------+
|    99.0000 |
+------------+
+---------------------+------+------+------+
| d                   | rw   | od   | nw   |
+---------------------+------+------+------+
| 2009-02-22 18:52:52 |    9 |  100 |   90 |
| 2009-02-22 18:52:52 |    5 |  100 |  110 |
| 2009-02-22 18:52:53 |    9 |   90 |   80 |
| 2009-02-22 18:52:53 |    1 |  100 |  110 |
| 2009-02-22 18:52:54 |    7 |  100 |   90 |
| 2009-02-22 18:52:54 |    3 |  100 |  110 |
| 2009-02-22 18:52:55 |    7 |   90 |   80 |
| 2009-02-22 18:52:55 |    3 |  110 |  120 |
| 2009-02-22 18:52:56 |    8 |  100 |   90 |
| 2009-02-22 18:52:57 |    6 |  100 |   90 |
| 2009-02-22 18:52:57 |    9 |   80 |   90 |
| 2009-02-22 18:52:58 |    9 |   90 |   80 |
| 2009-02-22 18:52:58 |    8 |   90 |  100 |
| 2009-02-22 18:52:59 |    4 |  100 |   90 |
| 2009-02-22 18:52:59 |    8 |  100 |  110 |
| 2009-02-22 18:53:00 |    7 |   80 |   70 |
| 2009-02-22 18:53:00 |    1 |  110 |  120 |
| 2009-02-22 18:53:01 |    3 |  120 |  110 |
| 2009-02-22 18:53:01 |    4 |   90 |  100 |
+---------------------+------+------+------+
+----------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table                      | Create Table                                                                                                                                                                                    |
+----------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| table10_innodb_int_autoinc | CREATE TABLE `table10_innodb_int_autoinc` (
  `pk` int(11) NOT NULL AUTO_INCREMENT,
  `int` int(11) DEFAULT NULL,
  PRIMARY KEY (`pk`)
) ENGINE=InnoDB AUTO_INCREMENT=11 DEFAULT CHARSET=latin1 |
+----------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Note: As each transaction is performing a +10 and a -10 change, if all updates were performed the average will be 100.

If you look at the 'zzlog' table you will notice that only one update was performed for the transaction at 2009-02-22 18:52:56 (a decrease of 10 - explaining the 99 average).

If you look the master.log file (attached you will see the the '+10' update logged but the trigger (updating the log table) isn't

If you look at the binlog output (attached) you will notice only one update at 2009-02-22 18:52:56 and not two as with the other transactions.  

No errors logged in the master.err file (attached)

Suggested fix:
Translations should perform either all statements or none
[22 Feb 2009 16:39] Omer Barnir
sql file to demonstate the failiure

Attachment: trans_fail.sql (text/x-sql), 3.72 KiB.

[22 Feb 2009 16:40] Omer Barnir
Server log file

Attachment: master.out (application/octet-stream, text), 6.76 KiB.

[22 Feb 2009 16:40] Omer Barnir
Binlog output

Attachment: binlog.out (application/octet-stream, text), 27.20 KiB.

[22 Feb 2009 16:41] Omer Barnir
Master error file

Attachment: master.err (application/octet-stream, text), 1.49 KiB.

[22 Feb 2009 21:01] Jørgen Løland
The problem has been observed both with InnoDB and Falcon