Bug #28090 Falcon Concurrent UPDATEs leading to assertion
Submitted: 25 Apr 2007 9:55 Modified: 30 Apr 2007 14:07
Reporter: Hakan Küçükyılmaz Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0.0-alpha OS:Any
Assigned to: Kevin Lewis CPU Architecture:Any

[25 Apr 2007 9:55] Hakan Küçükyılmaz
Description:
Concurrent UPDATEs leading to assertion.

Sample output:

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 ?? ()

How to repeat:
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();
[25 Apr 2007 9:56] Hakan Küçükyılmaz
Related to Bug#25557.
[29 Apr 2007 2:57] Kevin Lewis
When I tried this on my Windows laptop, I found a reproduceable assert that indicated a transaction was being completed twice.  The problem was in TransactionManager::startTransaction, when transactionSequence is assigned to a Transaction and incremented, it can be done under a shared lock for activeTransactions.syncObject if there is an available transaction with no dependencies.  This possibility was introduced as a performance enhancement to keep threads from backing up in startTransaction().

I incremented transactionSequence with INTERLOCKED_INCREMENT() and the problem went away.  My laptop was able to run three of these stored procedures to completion.  This may be related to the call stack that Hakan reported on Linux, but maybe not.  Hakan, please see if the other problem still exists.
[29 Apr 2007 22:14] Hakan Küçükyılmaz
I could successfully run the test with three and five concurrent clients. Output  of my run with five clients:

+--------+
| 999998 |
+--------+
1 row in set (1 hour 41 min 40.80 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (1 hour 41 min 40.80 sec)

+-----+
| end |
+-----+
| end |
+-----+
1 row in set (1 hour 41 min 40.81 sec)

+--------+
| v      |
+--------+
| 999999 |
+--------+
1 row in set (1 hour 41 min 40.81 sec)

+--------+
| update |
+--------+
| update |
+--------+
1 row in set (1 hour 41 min 40.81 sec)

+-----+
| end |
+-----+
| end |
+-----+
1 row in set (1 hour 41 min 40.81 sec)

Query OK, 0 rows affected (1 hour 41 min 40.81 sec)

Best regards,

Hakan
[30 Apr 2007 14:07] MC Brown
A note has been added to 6.0.0 changelog.