| Bug #28029 | SERIALIZABLE isn't. | ||
|---|---|---|---|
| Submitted: | 23 Apr 2007 17:40 | Modified: | 5 Mar 2008 12:22 |
| Reporter: | David Sharnoff | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | 5.0.22 | OS: | Linux |
| Assigned to: | Heikki Tuuri | CPU Architecture: | Any |
[23 Apr 2007 17:44]
David Sharnoff
pre-release OOPS-0.1009
Attachment: OOPS-0.1009.tar.gz (application/x-gzip, text), 169.85 KiB.
[23 Apr 2007 17:48]
David Sharnoff
full query log
Attachment: full-query-log.txt.gz (application/x-gzip, text), 302.46 KiB.
[23 Apr 2007 20:53]
Sveta Smirnova
Thank you for the report. Please indicate accurate version of MySQL server you met the problem with.
[23 Apr 2007 20:58]
Sveta Smirnova
Found in the initial post:
"ii mysql-server-4.1 4.1.15-1ubuntu5
mysql database server binaries"
If version of your MySQL server is 4.1.15, please, upgrade to current 4.1.22, because 4.1.15 is quite old and many bugs were fixed since it has been released.
[23 Apr 2007 22:48]
David Sharnoff
It was 4.1.15. I've upgraded to 5.0.22 and it has the same problem.
I'll attach a fresh query log.
Just fyi, the way my test script fails is always about the same.
This is an example:
not ok 133 - line622/898 # reference counts are off - 12 object [ add-1 #51 ]
reference count of *217 is off: 139 recorded, but should be 142 [add-1]
reference count of *7191 is off: recorded, but should be 10 [add-1]
reference count of *233 is off: 139 recorded, but should be 142 [add-1]
reference count of *249 is off: 139 recorded, but should be 142 [add-1]
reference count of *265 is off: 139 recorded, but should be 142 [add-1]
reference count of *185 is off: 139 recorded, but should be 142 [add-1]
reference count of *153 is off: 139 recorded, but should be 142 [add-1]
reference count of *137 is off: 139 recorded, but should be 142 [add-1]
reference count of *121 is off: 139 recorded, but should be 142 [add-1]
reference count of *201 is off: 139 recorded, but should be 142 [add-1]
reference count of *169 is off: 139 recorded, but should be 142 [add-1]
reference count of *7321 is off: 1 recorded, but should be 0 [add-1]
[add-1]
Bail out! ... early so the error doesn't scroll away [add-1]
My installed versions:
ii libdbd-mysql-perl 3.0002-2build1 A Perl5 database interface to the MySQL data
ii libmysqlclient10 3.23.56-3 LGPL-licensed client library for MySQL datab
rc libmysqlclient12 4.0.24-10ubuntu2.3 mysql database client library
ii libmysqlclient14 4.1.15-1ubuntu5 mysql database client library
ii libmysqlclient15off 5.0.22-0ubuntu6.06.3 mysql database client library
ii libqt3-mt-mysql 3.3.6-1ubuntu6.1 MySQL database driver for Qt3 (Threaded)
ii mysql-client-5.0 5.0.22-0ubuntu6.06.3 mysql database client binaries
ii mysql-common 5.0.22-0ubuntu6.06.3 mysql database common files (e.g. /etc/mysql
ii mysql-server-5.0 5.0.22-0ubuntu6.06.3 mysql database server binaries
ii python-mysqldb 1.2.1c3-4ubuntu4 A Python interface to MySQL
ii python2.4-mysqldb 1.2.1c3-4ubuntu4 A Python interface to MySQL
ii www-mysql 0.5.7-19ubuntu1 a WWW interface for the TCX mySQL database
Here is the fresh except of the query log that shows where SERIALIZABLE
is violated.
709 Connect muir@localhost on rectangle
709 Query set autocommit=0
709 Query SET SESSION TRANSACTION ISOLATION LEVEL SERIALIZABLE
709 Query SELECT o.* FROM charm2object AS o, charm2object AS og WHERE og.id = '111' AND og.loadgroup = o.loadgroup
712 Connect muir@localhost on rectangle
712 Query set autocommit=0
712 Query SET SESSION TRANSACTION ISOLATION LEVEL SERIALIZABLE
712 Query SELECT o.* FROM charm2object AS o, charm2object AS og WHERE og.id = '111' AND og.loadgroup = o.loadgroup
712 Query UPDATE charm2object SET loadgroup = '112', class = 'HASH', otype = 'H', virtual = '0', reftarg = '0', alen = '0', refs = '1', gcgeneration = '99', counter = (counter + 1) % 65536 WHERE id = '111'
712 Query commit
712 Quit
709 Query UPDATE charm2object SET loadgroup = '112', class = 'HASH', otype = 'H', virtual = '0', reftarg = '0', alen = '0', refs = '1', gcgeneration = '99', counter = (counter + 1) % 65536 WHERE id = '111'
709 Query commit
709 Quit
-Dave
[23 Apr 2007 22:50]
David Sharnoff
Exerpt of the query log, run with 5.0.22
Attachment: excerpt-2.txt (text/plain), 1.09 KiB.
[23 Apr 2007 22:50]
David Sharnoff
Full query log, 2nd run, 5.0.22
Attachment: full-query-log-2.txt.gz (application/x-gzip, text), 331.12 KiB.
[23 Apr 2007 22:51]
David Sharnoff
mysql dump as of the end of the 2nd run (5.0.22)
Attachment: mysqldump-2.txt.gz (application/x-gzip, text), 278.38 KiB.
[24 Apr 2007 5:11]
Heikki Tuuri
David, please check that those tables really are InnoDB, and not MyISAM. Are you sure that both statements really update the same, existing row? One of them should wait until the other commits. Regards, Heikki
[24 Apr 2007 16:21]
David Sharnoff
The CREATE TABLE statements are in the attached full query log. They include "TYPE = InnoDB". I don't think my tests would get as far as they do if I was using MyISAM. Both update the same existing row. The query log is complete: it starts with CREATE TABLE... Perhaps the Severity should be Critial instead?
[24 Apr 2007 18:01]
David Sharnoff
I tried added "LOCK IN SHARE MODE" to my SELECTs and that did not help. I'll attach a query log and exerpt for this latest run. It died faster this time (dumb luck, I think) so the log is shorter.
[24 Apr 2007 18:02]
David Sharnoff
LOCK IN SHARE MODE exerpt
Attachment: exerpt-3.txt (text/plain), 1.13 KiB.
[24 Apr 2007 18:03]
David Sharnoff
LOCK IN SHARE MODE full query log
Attachment: full-query-log-3.txt.gz (application/x-gzip, text), 55.25 KiB.
[2 May 2007 17:28]
Heikki Tuuri
David, please use SHOW CREATE TABLE ... to verify that the tables are not MyISAM. --Heikki
[2 May 2007 18:00]
David Sharnoff
show create table says "ENGINE=InnoDB" for both of the critical tables. I had previously attached a mysqldump of the database and query logs that include the CREATE TABLE statements.
[7 May 2007 17:12]
Heikki Tuuri
David, could the problem be that you use: id = '111' in the WHERE clause, though id is nunmeric, and '111' is a character string? Regards, Heikki
[7 May 2007 17:22]
David Sharnoff
I didn't write DBI, DBD::mysql, or any part of mysql so I don't know how my strings/numbers get encoded/decoded as they are passed to mysql. I don't explicitly use quotes. They are added by DBI or DBD::mysql. Since my application works perfectly (though slowly) when I add "FOR UPDATE" to all my queries, I'm pretty sure that number/string issues are not the problem.
[14 May 2007 17:03]
Heikki Tuuri
David, you have also filed http://bugs.mysql.com/bug.php?id=20857 about automatic deadlock detection failing (and the lock wait timeout kicking in). What is the connection of that bug report to this? Regards, Heikki
[14 May 2007 18:50]
David Sharnoff
As far as I know there is no connection except that they are triggered by similar code.
[4 Mar 2008 17:10]
Heikki Tuuri
David, were you able to determine where the bug was/is? --Heikki
[5 Mar 2008 8:09]
David Sharnoff
This appears to be fixed in 5.0.45.
[5 Mar 2008 12:22]
Heikki Tuuri
Closing the bug report, though I do not know what change could have fixed this.
Description: With SET SESSION TRANSACTION ISOLATION LEVEL SERIALIZABLE, two transactions start. They both read the same data. They both modify the same data. They both commit. Here is an except from my query log: 655 Connect muir@localhost on rectangle 655 Query set autocommit=0 655 Query SET SESSION TRANSACTION ISOLATION LEVEL SERIALIZABLE 655 Query SELECT o.* FROM charm2object AS o, charm2object AS og WHERE og.id = '111' AND og.loadgroup = o.loadgroup 657 Connect muir@localhost on rectangle 657 Query set autocommit=0 657 Query SET SESSION TRANSACTION ISOLATION LEVEL SERIALIZABLE 657 Query SELECT o.* FROM charm2object AS o, charm2object AS og WHERE og.id = '111' AND og.loadgroup = o.loadgroup 655 Query UPDATE charm2object SET loadgroup = '112', class = 'HASH', otype = 'H', virtual = '0', reftarg = '0', alen = '0', refs = '1', gcgeneration = '99', counter = (counter + 1) % 65536 WHERE id = '111' 655 Query commit 070423 9:58:50 655 Quit 657 Query UPDATE charm2object SET loadgroup = '112', class = 'HASH', otype = 'H', virtual = '0', reftarg = '0', alen = '0', refs = '1', gcgeneration = '99', counter = (counter + 1) % 65536 WHERE id = '111' 657 Query commit 657 Quit How to repeat: My enviroment: ubuntu 6.06 with the following mysql-related packages installed: ii libdbd-mysql-perl 3.0002-2build1 A Perl5 database interface to the MySQL data ii libmysqlclient10 3.23.56-3 LGPL-licensed client library for MySQL datab rc libmysqlclient12 4.0.24-10ubuntu2.3 mysql database client library ii libmysqlclient14 4.1.15-1ubuntu5 mysql database client library ii libmysqlclient15off 5.0.22-0ubuntu6.06.3 mysql database client library ii libqt3-mt-mysql 3.3.6-1ubuntu6.1 MySQL database driver for Qt3 (Threaded) ii mysql-client-4.1 4.1.15-1ubuntu5 mysql database client binaries ii mysql-common 5.0.22-0ubuntu6.06.3 mysql database common files (e.g. /etc/mysql rc mysql-common-4.1 4.1.12-1ubuntu3.4 mysql database common files (e.g. /etc/mysql ii mysql-server-4.1 4.1.15-1ubuntu5 mysql database server binaries ii python-mysqldb 1.2.1c3-4ubuntu4 A Python interface to MySQL ii python2.4-mysqldb 1.2.1c3-4ubuntu4 A Python interface to MySQL rc webmin-mysql 1.210a-2ubuntu1 mysql-server control module for webmin ii www-mysql 0.5.7-19ubuntu1 a WWW interface I'm working on a new relase of my perl OOPS module. I enclose a pre-release distribution of it. To repeat, install a number of dependent perl modules: DBI, DBD::mysql, Digest::Md5, Scalar::Util, Filter::Util::Call, Event, IO::Event, Test::MultiFork, Data::Compare, Clone::PP, BSD::Resource. Unpack my OOPS-0.1009 distribution. Goto the "t" directory. Run "gc.t". It may die quickly. It may run for a while. The failure is not predictable. This initial bug report screen doesn't give me a place to upload. As soon as I can, I'll upload my pre-release OOPS distribution and also my full query log.