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

[2 Jul 2009 9:24] victor godwin
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
[2 Jul 2009 10:11] Valeriy Kravchuk
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.
[2 Jul 2009 14:03] victor godwin
Valeriy,
thank you for your reply.
I remembered already try  using FORCE INDEX() a while ago.
But I will try again.
Thank you.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.043 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.