MySQL Bugs: #45901: Cannot do SELECT FOR UPDATE with small amount of records.

Bug #45901	Cannot do SELECT FOR UPDATE with small amount of records.
Submitted:	2 Jul 2009 9:24	Modified:	2 Jul 2009 14:03
Reporter:	victor godwin	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5,1.30, 5.1.33, 5.1.35, 5.1.36	OS:	Windows (XP)
Assigned to:		CPU Architecture:	Any
Tags:	innodb, locking, select for update

Description:
what I did:
I had a database with 1 table. The table had 3 columns. First column is primary key and second column is index.I filled it with 8 records.
I tried to do SELECT FOR UPDATE from 2 connections to the table.
I used 1st connection to SELECT FOR UPDATE 3 records . Then I used 2nd connection to SELECT FOR UPDATE 4 records within the same table. I used WHERE clause from index not from primary key.

what I wanted to happen:
I want to see 3 records from 1st connection and 4 records from 2nd connection.

what actually happened:
SELECT FOR UPDATE from 2nd connection failed and "ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction" message came out.

result from "show innodb status\G"
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
090702 15:59:19 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 59 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4, signal count 4
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 8, OS waits 4; RW-excl spins 0, OS waits 0
------------
TRANSACTIONS
------------
Trx id counter 0 8985
Purge done for trx's n:o < 0 8974 undo n:o < 0 0
History list length 19
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 8982, not started, OS thread id 1880
MySQL thread id 4, query id 35 localhost 127.0.0.1 root
show innodb status
---TRANSACTION 0 0, not started, OS thread id 3004
MySQL thread id 3, query id 9 localhost 127.0.0.1 root
---TRANSACTION 0 8984, ACTIVE 2 sec, OS thread id 2808 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320, 1 row lock(s)
MySQL thread id 2, query id 34 localhost 127.0.0.1 root Sending data
select * from d where d2='002' for update
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 57 n bits 80 index `PRIMARY` of table `cd`.`d` trx id 0 8984 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 3; hex 313031; asc 101;; 1: len 6; hex 00000000230f; asc     # ;; 2: len 7; hex 800000002d0110; asc     -  ;; 3: len 3; hex 303031; asc 001;;
4: len 2; hex 3131; asc 11;;

------------------
---TRANSACTION 0 8983, ACTIVE 30 sec, OS thread id 2408
4 lock struct(s), heap size 320, 7 row lock(s)
MySQL thread id 1, query id 30 localhost 127.0.0.1 root
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
74 OS file reads, 62 OS file writes, 29 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 195193, node heap has 1 buffer(s)
0.00 hash searches/s, 0.14 non-hash searches/s
---
LOG
---
Log sequence number 0 510827
Log flushed up to   0 510827
Last checkpoint at  0 510827
0 pending log writes, 0 pending chkp writes
26 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 58338738; in additional pool allocated 1405440
Dictionary memory allocated 28024
Buffer pool size   3008
Free buffers       2943
Database pages     64
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 64, created 0, written 37
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 3920, state: waiting for server activity
Number of rows inserted 8, updated 0, deleted 0, read 3
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.05 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

note:
I did some trial and error with another data pattern. It seems that this pattern came out:
Table with 6 or 7 record had this bug when I SELECT FOR UPDATE 3 records.
Table with 8 record had this bug when I SELECT FOR UPDATE 4 records.

SELECT FOR UPDATE running well when the table had 5 or less records.
SELECT FOR UPDATE running well when the table had 9 or more records. I only check with 10,19,20 records though.

I found that this bug happened when "row locks"(from "show innodb status") amount same with the actual records. 
Example:
4 records had 4 row locks
3 records had 3 row locks

I am not sure about the above pattern I found have any connections with this problem. Maybe I just missed the configuration or using wrong index. 

How to repeat:
using default my.ini file.

connection 1:
CREATE DATABASE CD;

USE CD;

CREATE TABLE d (
                d1 VARCHAR(10) NOT NULL,
                d2 VARCHAR(10) NOT NULL,
                d3 VARCHAR(10) NOT NULL,
                PRIMARY KEY (d1)
);

CREATE INDEX d2	ON d (d2);

insert  into `d`(`d1`,`d2`,`d3`) values ('101','001','11');
insert  into `d`(`d1`,`d2`,`d3`) values ('102','001','12');
insert  into `d`(`d1`,`d2`,`d3`) values ('103','001','13');
insert  into `d`(`d1`,`d2`,`d3`) values ('201','002','21');
insert  into `d`(`d1`,`d2`,`d3`) values ('202','002','22');
insert  into `d`(`d1`,`d2`,`d3`) values ('203','002','23');
insert  into `d`(`d1`,`d2`,`d3`) values ('204','002','24');
insert  into `d`(`d1`,`d2`,`d3`) values ('301','003','31');

begin;select * from d where d2='001' for update;

(result)
Query OK, 0 rows affected (0.00 sec)

+-----+-----+----+
| d1  | d2  | d3 |
+-----+-----+----+
| 101 | 001 | 11 |
| 102 | 001 | 12 |
| 103 | 001 | 13 |
+-----+-----+----+
3 rows in set (0.01 sec)

connection 2:
begin;select * from d where d2='002' for update;

(result)
Query OK, 0 rows affected (0.00 sec)

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

Suggested fix:
unknown

Sorry, but this is NOT a bug. Look:

mysql> explain select * from d where d2='002'\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: d
         type: ALL
possible_keys: d2
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 8
        Extra: Using where
1 row in set (0.02 sec)

So, optimizer decided to read the entire table (ALL), because you are reading too many rows (4 out of 8 total) based on its etimations. (For d2 = '001' optimizer decides to use index, check it.) 

As you do SELECT ... FOR UPDATE, server will try to set X lock on every row (including those 3 X locked by other connection), hence the result you get.

You can try to workaround this situation by forcing d2 index usage always, like this:

select * from d force index(d2) where d2 = '002' for update;

To summarize, this is not a bug.

Valeriy,
thank you for your reply.
I remembered already try  using FORCE INDEX() a while ago.
But I will try again.
Thank you.