Bug #12947 InnoDB: consistent read can return inconsistent results, even crash possible
Submitted: 2 Sep 2005 11:35 Modified: 4 Sep 2005 3:02
Reporter: Heikki Tuuri Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.0.8? - 5.0.12 OS:Linux (Linux/x86)
Assigned to: Heikki Tuuri CPU Architecture:Any

[2 Sep 2005 11:35] Heikki Tuuri
Description:
Run 10 minutes:

heikki@hundin:~/test> perl ibtest3 > out3 &
[1] 22864
heikki@hundin:~/test>
heikki@hundin:~/test>
heikki@hundin:~/test> perl ibtest3a > out3a &
[2] 22868
heikki@hundin:~/test> perl ibtest3b > out3b &
[3] 22873
heikki@hundin:~/test>
heikki@hundin:~/test>
heikki@hundin:~/test>
heikki@hundin:~/test>
heikki@hundin:~/test> perl ibtest3c > out3c &
[4] 22878
heikki@hundin:~/test>

heikki@hundin:~/mysql-5.0/sql> ./mysqld
InnoDB: The first specified data file /home/heikki/data/ibdata1 did not exist:
InnoDB: a new database to be created!
050902 14:24:34  InnoDB: Setting file /home/heikki/data/ibdata1 size to 20 MB
InnoDB: Database physically writes the file full: wait...
050902 14:24:35  InnoDB: Log file /home/heikki/data/ib_logfile0 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile0 size to 128 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
050902 14:24:48  InnoDB: Log file /home/heikki/data/ib_logfile1 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile1 size to 128 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050902 14:25:04  InnoDB: Started; log sequence number 0 0
050902 14:25:04 [Warning] mysql.user table is not updated to new password format
; Disabling new password usage until mysql_fix_privilege_tables is run
050902 14:25:04 [Note] ./mysqld: ready for connections.
Version: '5.0.13-beta-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307
Source distribution

Error: index `D` of table `test/blobt3` contains 673 entries, should be 671
Error: index `A` of table `test/blobt3` contains 674 entries, should be 671
Error: index `C` of table `test/blobt3` contains 672 entries, should be 671
Error: index `B` of table `test/blobt3` contains 674 entries, should be 671

How to repeat:
I have attached the test programs.
[2 Sep 2005 11:36] Heikki Tuuri
ibtest Perl programs and the my.cnf

Attachment: ibtest33a3b3c.txt (text/plain), 14.98 KiB.

[2 Sep 2005 11:44] Heikki Tuuri
The bug happens also with just ibtest3 and ibtest3a.

heikki@hundin:~/mysql-5.0/sql> ./mysqld
050902 14:57:17  InnoDB: Started; log sequence number 0 1369330889
050902 14:57:17 [Warning] mysql.user table is not updated to new password format
; Disabling new password usage until mysql_fix_privilege_tables is run
050902 14:57:17 [Note] ./mysqld: ready for connections.
Version: '5.0.13-beta-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307
Source distribution
Error: index `D` of table `test/blobt3` contains 654 entries, should be 653
Error: index `A` of table `test/blobt3` contains 655 entries, should be 653
[2 Sep 2005 12:25] Heikki Tuuri
I was not able to repeat this with 4.1.15 or 5.0.4.
[2 Sep 2005 13:07] Heikki Tuuri
I was not able to repeat this with mysqld-standard-5.0.11.

The bug may be associated with the recent changes made to support a read view of a cursor.

With 5.0.13-debug I can repeat this in 3 minutes, running 3, 3a, 3b, 3c, and doing in the client:

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | error    | Corrupt  |
+-------------+-------+----------+----------+
1 row in set (1.25 sec)

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | status   | OK       |
+-------------+-------+----------+----------+
1 row in set (1.24 sec)

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | status   | OK       |
+-------------+-------+----------+----------+
1 row in set (1.30 sec)

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | status   | OK       |
+-------------+-------+----------+----------+
1 row in set (1.32 sec)

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | status   | OK       |
+-------------+-------+----------+----------+
1 row in set (1.47 sec)

mysql> check table blobt3;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| test.blobt3 | check | error    | Corrupt  |
+-------------+-------+----------+----------+
1 row in set (1.55 sec)

mysql>
[2 Sep 2005 16:45] Heikki Tuuri
5.0.10 seems to work ok.

With 5.0.13, the problems seems to be that a consistent read cursor sometimes returns extra rows.

mysql> select a, length(b), length(c) from blobt3 order by a;
+-----+-----------+-----------+
| a   | length(b) | length(c) |
+-----+-----------+-----------+
| 571 |     44634 |     44634 |
| 714 |     44634 |     29824 |
| 714 |     44634 |     29824 |
| 714 |     29824 |     29824 |
| 857 |     14879 |     14879 |
| 857 |     29824 |     14879 |
| 857 |     29824 |     14879 |
+-----+-----------+-----------+
7 rows in set (0.44 sec)

mysql> select a, length(b), length(c) from blobt3 order by a;
+-----+-----------+-----------+
| a   | length(b) | length(c) |
+-----+-----------+-----------+
| 571 |     44634 |     44634 |
| 714 |     44634 |     29824 |
| 714 |     44634 |     29824 |
| 857 |     14879 |     14879 |
| 857 |     29824 |     14879 |
| 857 |     29824 |     14879 |
+-----+-----------+-----------+
6 rows in set (1.11 sec)

mysql> select a, length(b), length(c) from blobt3 order by a;
+-----+-----------+-----------+
| a   | length(b) | length(c) |
+-----+-----------+-----------+
| 571 |     44634 |     44634 |
| 714 |     44634 |     29824 |
| 714 |     44634 |     29824 |
| 857 |     29824 |     14879 |
| 857 |     29824 |     14879 |
+-----+-----------+-----------+
5 rows in set (0.62 sec)

mysql>
[2 Sep 2005 18:52] Heikki Tuuri
I tested a self-compiled 5.0.10, and also that exhibited the bug.
[2 Sep 2005 22:19] Heikki Tuuri
The bug was that in row_search_for_mysql(), we used page_rec_is_comp() to a record that was not on any page! The record was an old version constructed for a consistent read.

This bug was introduced in the patch:
------------------------------------------------
D 1.90 05/04/25 10:14:26+03:00 marko@hundin.mysql.fi 150 149 181/170/3897
P innobase/row/row0sel.c
C Make use of page_rec_is_supremum() and page_rec_is_infimum().
C Turn some assertions into debug assertions.
C Add UNIV_LIKELY and UNIV_UNLIKELY hints.
C
C row_search_for_mysql(): Eliminate local variables "moved",
C "cons_read_requires_clust_rec", "was_lock_wait", "shortcut",
C "success" and "comp". Replace some of them with goto's.
C Disable variable "cnt" unless #ifdef UNIV_SEARCH_DEBUG.
------------------------------------------------

in version 5.0.5.
[2 Sep 2005 22:22] Bugs System
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/internals/29258
[2 Sep 2005 22:25] Heikki Tuuri
Introduced in 5.0.5, fixed in 5.0.13.
[4 Sep 2005 3:02] Paul Dubois
Noted in 5.0.13 changelog.
[11 Sep 2005 9:03] Heikki Tuuri
The bug was probably pushed to the 5.0 release tree around 5.0.8, not 5.0.5 as previously stated.