Bug #25557 Falcon: Unexpected error; "Record has changed since last read in table"
Submitted: 11 Jan 2007 21:46 Modified: 24 Apr 2007 23:13
Reporter: jocelyn fournier (Silver Quality Contributor) Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:5.2-Alpha OS:Linux (Linux)
Assigned to: CPU Architecture:Any
Tags: qc

[11 Jan 2007 21:46] jocelyn fournier
Description:
Hi,

On a simple table, concurrent updates could create a "Record has changed since last read in table" error.

How to repeat:
CREATE TABLE `stats_buffer` (
  `id_forum` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `id_cat` smallint(4) unsigned NOT NULL DEFAULT '0',
  `nb_vues` int(10) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`id_forum`,`id_cat`)
) ENGINE=Falcon DEFAULT CHARSET=latin1 

INSERT INTO stats_buffer VALUES (1,1,0),(2,1,0),(1,2,0),(2,2,0);

Do the following updates on several differents lines at the same time :

UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=1
UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=2 AND id_cat=1
UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=2
UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=2 AND id_cat=2

UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=1 AND id_cat=1
UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=2 AND id_cat=1
UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=1 AND id_cat=2
UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=2 AND id_cat=2

With this configuration and only doing those exact queries (no SELECT, no DELETE, no INSERT) on different lines cause the problem : 

Query : UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=8 AND id_cat=0

Error : Record has changed since last read in table 'stats_buffer'

(my original table contains about 865 lines)

Regards,
  Jocelyn Fournier
[17 Jan 2007 17:02] MySQL Verification Team
Thank you for the bug report. Looks this is a duplicate of bug:
http://bugs.mysql.com/bug.php?id=24970 with different test case.
Thanks in advance.
[17 Jan 2007 18:47] jocelyn fournier
Hi Miguel,

I don't have access to this one ;)

  Jocelyn
[17 Jan 2007 19:39] MySQL Verification Team
Hi Jocelyn,
Below is how to repeat of that bug:

Set up two connections. Call them T1 and T2:

On T1, do:

create table t25 (s1 int, s2 int) engine=falcon;
insert into t25 values (1,0);
delimiter //
create procedure p25 ()
begin
  declare v int default 0;
  while v < 10000 do
    select v;
    begin
      declare error_count int default 0;
      declare continue handler for 1020
      begin
        select 'error',error_count;
        if error_count = 0 then set error_count = 1; set v = v - 1; end if;
        end;
      select 'update';
      update t25 set s2 = s2 + 1 where s1 = 1;
      select 'commit';
      commit;
      select 'end';
      end;
    set v = v + 1;
    end while;
  end//
delimiter ;
commit;
set @@autocommit=0;
start transaction;
call p25();

On T2, while T1 is running, do:

call p25();

After a while, you'll see:

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (4.08 sec)

ERROR 1020 (HY000): Record has changed since last read in table 't25'
[17 Jan 2007 21:19] jocelyn fournier
Hi,

It seems to be indeed the same issue.

Thanks,
  Jocelyn
[18 Jan 2007 23:40] Ann Harrison
We've changed the error code to report that a concurrent transaction
changed the record.  The InnoDB behavior is very close to a dirty
write...  it's possible to update a record when a SELECT doesn't
return the most recent version.  Falcon's rule is quite simply that
if you can't read the most recent version, you can't update it either.
That avoids sequences like this ...

T1  select a from t1 where pk = 1;
     a
     1
T2  update t1 set a = a+1 where pk = 1;
T1  update t1 set a = a+1 where pk = 1;
     a
     3

That may seem like a trivial issue, but consider the case where you're
debiting an account balance and need to prevent the account from going
negative.
[19 Jan 2007 2:15] jocelyn fournier
Hi,

Actually in my case, each MySQL update query is done inside its own transaction (autocommit set to 1).
In this case they shouldn't be any "record has changed" error ?

Thanks,
  Jocelyn
[19 Jan 2007 13:32] Hakan Küçükyılmaz
I can't reproduce this behaviour with 5.2.1-falcon-alpha-debug:

[14:29] root@test>SET @@autocommit = 1;
Query OK, 0 rows affected (0.00 sec)

[14:29] root@test>CREATE TABLE `stats_buffer` (
    ->   `id_forum` tinyint(3) unsigned NOT NULL DEFAULT '0',
    ->   `id_cat` smallint(4) unsigned NOT NULL DEFAULT '0',
    ->   `nb_vues` int(10) unsigned NOT NULL DEFAULT '0',
    ->   PRIMARY KEY (`id_forum`,`id_cat`)
    -> ) ENGINE=Falcon DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (1.30 sec)

[14:29] root@test>INSERT INTO stats_buffer VALUES (1,1,0),(2,1,0),(1,2,0),(2,2,0);
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=2 AND id_cat=1;
Query OK, 1 row affected (0.04 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=2;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=2 AND id_cat=2;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=1 AND id_cat=1;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=2 AND id_cat=1;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=1 AND id_cat=2;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues-1 WHERE id_forum=2 AND id_cat=2;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[14:29] root@test>UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=8 AND id_cat=0;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 0  Changed: 0  Warnings: 0

Can you provide us with the exact steps on how to reproduce your described behaviour?

Best Regards,

Hakan
[19 Jan 2007 14:50] jocelyn fournier
Hi,

The issue appears under high load when several different connections update at the same time the table.
Perhaps running the p25 procedure modified to use autocommit 1 in two different connection could do the trick  ?

(I'll try to modify the store proc to reproduce the issue)

Thanks,
  Jocelyn
[19 Jan 2007 15:00] jocelyn fournier
Hi,

In T1 :

CREATE TABLE `stats_buffer` (
  `id_forum` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `id_cat` smallint(4) unsigned NOT NULL DEFAULT '0',
  `nb_vues` int(10) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`id_forum`,`id_cat`)
) ENGINE=Falcon DEFAULT CHARSET=latin1;

INSERT INTO stats_buffer VALUES (1,1,0),(2,1,0),(1,2,0),(2,2,0);
delimiter //
create procedure p25 ()
begin
  declare v int default 0;
  while v < 1000000 do
    select v;
    begin
      declare error_count int default 0;
      declare continue handler for 1020
      begin
        select 'error',error_count;
        if error_count = 0 then set error_count = 1; set v = v - 1; end if;
        end;
      select 'update';
      UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=1;
      select 'end';
      end;
    set v = v + 1;
    end while;
  end//
delimiter ;
call p25();

in T2 :

call p25();

I finally get :

+--------+
| update |
+--------+
| update | 
+--------+
1 row in set (1 min 58.23 sec)

ERROR 1020 (HY000): Record has changed since last read in table 'stats_buffer'
[19 Jan 2007 15:03] jocelyn fournier
Note with 3 concurrent calls, it almost fails immediately.

  Jocelyn
[19 Jan 2007 15:38] Ann Harrison
Unless the first transaction to modify a record is committed
before a second transaction starts, the second transaction
will get an error when it attempts to update the same record
in Repeatable Read mode.  In Repeatable Read, a transaction
does not see changes made by concurrent transactions - even
autocommit transactions.
[19 Jan 2007 15:53] jocelyn fournier
Hi,

Thanks for the clarification.
When do you plan to implement the READ-UNCOMMITED/READ-COMMITED support ?

Thanks,
  Jocelyn
[19 Jan 2007 16:05] Ann Harrison
Read uncommitted, probably never - Jim says "over my dead body",
and I don't want to take a chance that he's serious.  Read committed
is already implemented, I think.
[19 Jan 2007 16:22] jocelyn fournier
If I understand well, does that mean that concurrent updates on the same record on different connections will not be possible with Falcon ? (ie I cannot just convert MyISAM -> Falcon without redesigning my whole application ?)

Thanks,
  Jocelyn
[19 Jan 2007 17:10] Ann Harrison
I think that read committed will do what you want - allow
your transaction to wait and update the record when the
first transaction commits its changes.  

However, it's probably true that moving an application from
MyISAM to a transactional engine will require some thought
and modification.
[19 Jan 2007 17:31] jocelyn fournier
Hi,

If Read-Committed should do what I want, then there is a bug :)
I've just set the tx_isolation in READ-COMMITED and lauch p25() store procedure, and I got :

ERROR 1020 (HY000): Record has changed since last read in table 'stats_buffer'

Thanks,
  Jocelyn
[22 Jan 2007 11:11] MySQL Verification Team
Hi Jocelyn,

I was unable to repeat with your original test case, it is ok to put this
bug as duplicate of http://bugs.mysql.com/bug.php?id=24970 for you ?
Thanks in advance.
[22 Jan 2007 11:26] jocelyn fournier
Hi Miguel,

To reproduce :

In T1 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
CREATE TABLE `stats_buffer` (
  `id_forum` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `id_cat` smallint(4) unsigned NOT NULL DEFAULT '0',
  `nb_vues` int(10) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`id_forum`,`id_cat`)
) ENGINE=Falcon DEFAULT CHARSET=latin1;

INSERT INTO stats_buffer VALUES (1,1,0),(2,1,0),(1,2,0),(2,2,0);
delimiter //
create procedure p25 ()
begin
  declare v int default 0;
  while v < 1000000 do
    select v;
    begin
      declare error_count int default 0;
      declare continue handler for 1020
      begin
        select 'error',error_count;
        if error_count = 0 then set error_count = 1; set v = v - 1; end if;
        end;
      select 'update';
      UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=1;
      select 'end';
      end;
    set v = v + 1;
    end while;
  end//
delimiter ;
call p25();

in T2 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
call p25();

in T3 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
call p25();

This seems not to be a duplicate of 24970, since in 24970 the error occurs while in REPEATABLE-READ mode, inside a transaction.
However in my case, in READ-COMMITTED mode and with autocommit enabled by default, no error should occur.

Thanks,
  Jocelyn
[23 Jan 2007 11:32] MySQL Verification Team
Thank you for the feedback. Verified with latest test case.
[7 Feb 2007 1:02] Kevin Lewis
This problem has gotten very difficult to fix.  I've spent a couple days on it now and need to report my (lack of) progress.

The problem can be divided into what can be done with update conflicts using either (A) repeatable-read  or  (B) read-committed isolation.  This bug is currently refering to the read-committed case.

It seems logical that during the progress of a transaction, each change could easily be made to the most recent committed version of a record.  But in practice, using the MySQL architecture, it is more easily said than done.  The server is responsible for making a change in one or more fields within a record.  So it reads a record from the storage engine, makes the changes, and then writes the record.  Falcon does not use record locking, relying on record versioning instead.  So it is possible that the record read by the server in one thread has been changed before it gets written again.  I tried to have Falcon retry the update when a new record version is committed, but I finally realized that the retry has to be done at the server.

Innodb uses record and table locking to achieve the desired isolation.  This works well for read-committed isolation, but allows a transaction with repeatable-read isolation to change a record that it cannot see. It changes the newly committed record, even though it was not part of the table when the transaction begain.

So here is the timeline;
Thread A:  Read the current record version to update a field.
           - Innodb locks the record, Falcon does not.
Thread B:  Read the same record version to update a field.
           - Innodb blocks on the record lock, Falcon returns it.
Thread A:   MySQL server changes appropriate field.
Thread B:   MySQL server changes appropriate field for Falcon.
Thread A:   Update and commit a new record version.  
            - Innodb reads the newly committed record.
Thread B:   MySQL server changes appropriate field for Innodb
Thread B:   Update the record
            - Innodb has waited for the commit.  
            - Falcon waited if the update came in while 
              thread A was still uncommitted.
            -- Innodb reads and updated the committed record.
            -- Falcon reads the uncommitted record and returns 
               an Update Conflict.  

In order for Falcon to succeed in instances where transactions can be serialized without compromizing transaction isolation, it will require the MySQL engine to retry the read when it gets one of these update conflicts.  The Falcon engine canot do the retry itself because the record being changed has previously been read without a record lock.  If the record has been changed by a more recent transaction, Falcon must assume that the older record was read.  With repeatable-read, it definitely was.  With read-committed, it is not known for sure which record version was read.  This is important when the update is like this;   UPDATE t SET a = a + 10;  This is true for deletes also; DELETE FROM t WHERE (a = b);
[12 Feb 2007 14:12] Kevin Lewis
I opened WL#3715 to describe and track this fix as it is made in the server code.  I am not sure who will do the work, so I am assigning it to Calvin for now.
[16 Feb 2007 15:17] Kevin Lewis
As Calvin requested, this is unassigned for now.
Lets use this Bug number to track the problem of unexpected Update Conflicts for both Read-Committed and Repeatable-Read since Bug#24970 is specifically targeted at the stored procedure not handling the SQL error 1020.
[21 Mar 2007 18:12] Matthias Leich
Please have a look at 
Bug#27350 test-insert, Unexpected error; "Record has changed since last read
          in table"
There we get the same wrong error message during high load but without
any concurrency. Maybe both bugs have the same reason.
If yes, my Bug#27350 should be of course the duplicate :)
[14 Apr 2007 19:36] Hakan Küçükyılmaz
Still fails.
[18 Apr 2007 21:55] Hakan Küçükyılmaz
I used Jocelyn's comment for reproducing:

 [22 Jan 12:26] jocelyn fournier

Hi Miguel,

To reproduce :

In T1 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
CREATE TABLE `stats_buffer` (
  `id_forum` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `id_cat` smallint(4) unsigned NOT NULL DEFAULT '0',
  `nb_vues` int(10) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`id_forum`,`id_cat`)
) ENGINE=Falcon DEFAULT CHARSET=latin1;

INSERT INTO stats_buffer VALUES (1,1,0),(2,1,0),(1,2,0),(2,2,0);
delimiter //
create procedure p25 ()
begin
  declare v int default 0;
  while v < 1000000 do
    select v;
    begin
      declare error_count int default 0;
      declare continue handler for 1020
      begin
        select 'error',error_count;
        if error_count = 0 then set error_count = 1; set v = v - 1; end if;
        end;
      select 'update';
      UPDATE stats_buffer SET nb_vues=nb_vues+1 WHERE id_forum=1 AND id_cat=1;
      select 'end';
      end;
    set v = v + 1;
    end while;
  end//
delimiter ;
call p25();

in T2 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
call p25();

in T3 :

SET GLOBAL tx_isolation="READ-COMMITTED";
SET tx_isolation="READ-COMMITTED";
call p25();

This time we get a crash:

Client 1:
+--------+
| v      |
+--------+
| 592757 |
+--------+
1 row in set (39 min 11.33 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (39 min 11.33 sec)

Client 2:
+--------+
| v      |
+--------+
| 588542 |
+--------+
1 row in set (39 min 6.05 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (39 min 6.05 sec)

Client 3:
+--------+
| v      |
+--------+
| 588233 |
+--------+
1 row in set (38 min 58.84 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (38 min 58.84 sec)

Backtrace is:
Program received signal SIGILL, Illegal instruction.
[Switching to Thread 1141946720 (LWP 3133)]
0x00002b67703f12ac in raise () from /lib/libpthread.so.0
(gdb) bt
#0  0x00002b67703f12ac in raise () from /lib/libpthread.so.0
#1  0x00000000008a2958 in Error::debugBreak () at Error.cpp:93
#2  0x00000000008a2a71 in Error::error (string=0xc1b568 "assertion failed at line %d in file %s\n")
    at Error.cpp:70
#3  0x00000000008a2b07 in Error::assertionFailed (fileName=0xc139e7 "Transaction.cpp", line=655)
    at Error.cpp:77
#4  0x000000000086de26 in Transaction::writeComplete (this=0x2aaaab166598) at Transaction.cpp:655
#5  0x00000000009003ec in SerialLogTransaction::commit (this=0x2aaaadf67470) at SerialLogTransaction.cpp:78
#6  0x0000000000900453 in SerialLogTransaction::doAction (this=0x2aaaadf67470)
    at SerialLogTransaction.cpp:132
#7  0x00000000008fa914 in SerialLog::gopherThread (this=0x2aaaaaf3e3a8) at SerialLog.cpp:145
#8  0x00000000008faa19 in SerialLog::gopherThread (arg=0x2aaaaaf3e3a8) at SerialLog.cpp:124
#9  0x000000000086adb1 in Thread::thread (this=0x2aaaab051fa0) at Thread.cpp:161

(gdb) f 4
#4  0x000000000086de26 in Transaction::writeComplete (this=0x2aaaab166598) at Transaction.cpp:655
655             ASSERT(writePending == true);
(gdb) p writePending
$1 = false
(gdb)
[24 Apr 2007 21:59] Jim Starkey
With the data given, I don't understand how the original error could have occurred (there are no records with id_forum=8), but it is possible it did on the original data.  If that was the case, the change to InnoDB semantics for fetch for update probably fixed the problem anyway.
[24 Apr 2007 23:13] jocelyn fournier
Hi Jim,

You should not use the data given initially, but the testcase provided at the end of the bug report.

Thanks,
  Jocelyn
[25 Apr 2007 0:32] Hakan Küçükyılmaz
Hitting assertion.

Client 1:

+--------+
| v      |
+--------+
| 204124 |
+--------+
1 row in set (13 min 21.49 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (13 min 21.49 sec)

Client 2:

+--------+
| v      |
+--------+
| 198124 |
+--------+
1 row in set (13 min 10.51 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (13 min 10.51 sec)

+-----+
| end |
+-----+
| end |
+-----+
1 row in set (13 min 10.51 sec)

Client 3:

+--------+
| v      |
+--------+
| 196724 |
+--------+
1 row in set (12 min 56.80 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (12 min 56.80 sec)

+-----+
| end |
+-----+
| end |
+-----+
1 row in set (12 min 56.81 sec)

(gdb) f 4
#4  0x000000000086e1bc in Transaction::writeComplete (this=0x2aaaab00dda0) at Transaction.cpp:695
695             ASSERT(writePending == true);
(gdb) p writePending
$1 = 238
(gdb)

Program received signal SIGILL, Illegal instruction.
[Switching to Thread 1141680480 (LWP 20178)]
0x00002b9588c1f2ac in raise () from /lib/libpthread.so.0
(gdb) bt
#0  0x00002b9588c1f2ac in raise () from /lib/libpthread.so.0
#1  0x00000000008a323c in Error::debugBreak () at Error.cpp:92
#2  0x00000000008a3355 in Error::error (string=0xc1c368 "assertion failed at line %d in file %s\n")
    at Error.cpp:69
#3  0x00000000008a33eb in Error::assertionFailed (fileName=0xc14687 "Transaction.cpp", line=695) at Error.cpp:76
#4  0x000000000086e1bc in Transaction::writeComplete (this=0x2aaaab00dda0) at Transaction.cpp:695
#5  0x0000000000900db8 in SerialLogTransaction::commit (this=0x2aaaadccb168) at SerialLogTransaction.cpp:77
#6  0x0000000000900e1f in SerialLogTransaction::doAction (this=0x2aaaadccb168) at SerialLogTransaction.cpp:131
#7  0x00000000008fb2e0 in SerialLog::gopherThread (this=0x2aaaaaf3e3a8) at SerialLog.cpp:144
#8  0x00000000008fb3e5 in SerialLog::gopherThread (arg=0x2aaaaaf3e3a8) at SerialLog.cpp:123
#9  0x000000000086b131 in Thread::thread (this=0x2aaaab0522d8) at Thread.cpp:160
#10 0x000000000086b34b in Thread::thread (parameter=0x2aaaab0522d8) at Thread.cpp:139
#11 0x00002b9588c18f1a in start_thread () from /lib/libpthread.so.0
#12 0x00002b95892cd602 in clone () from /lib/libc.so.6
#13 0x0000000000000000 in ?? ()
(gdb) f 4
[25 Apr 2007 9:55] Hakan Küçükyılmaz
Assertion failure is opened as new Bug #28090.