MySQL Bugs: #109938: next key lock with ROLLBACK TO SAVEPOINT

Bug #109938	next key lock with ROLLBACK TO SAVEPOINT
Submitted:	4 Feb 2023 21:51	Modified:	10 Feb 2023 18:24
Reporter:	Moataz Zuhari	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S3 (Non-critical)
Version:	8.0.31	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
I faced multiple locking issues with `ROLLBACK TO SAVEPOINT` command, 

its like the next key lock will happen if i have insert command after SAVEPOINT and then  ROLLBACK TO SAVEPOINT 
the next key lock will happen for the table in the insert query 

if i use RELEASE SAVEPOINT instead ROLLBACK TO SAVEPOINT the x lock will not happen, very weird behavior, no ?
 
is there a wrong behavior when use ROLLBACK TO SAVEPOINT ??  why the next key lock happen in this case ? 

I use the latest versions from mysql.

my transaction type: REPEATABLE READ 

And this the TRANSACTION output from the SHOW ENGINE INNODB STATUS that have relevant to this issue 

INSERT INTO book (id, name)
VALUES (950, 'test_book_950')
------- TRX HAS BEEN WAITING 17 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 383 page no 4 n bits 72 index PRIMARY of table `test`.`book` trx id 286322 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

How to repeat:
Suppose i have this table with some dats: 

CREATE TABLE book (
  id int NOT NULL,
  name varchar(64) NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB;

INSERT INTO book (id, name) VALUES (700, 'test_book_700');
INSERT INTO book (id, name) VALUES (750, 'test_book_750');
INSERT INTO book (id, name) VALUES (800, 'test_book_800');
 

and then i have two connections to mysql server:

=========
Connection #1:

START TRANSACTION;

SELECT * FROM  book WHERE name = 'test_book_700';

SAVEPOINT sa_savepoint_1;

INSERT INTO book (id, name) VALUES (900, 'test_book_900');

ROLLBACK TO SAVEPOINT sa_savepoint_1;

 => x_lock will happen for the id > 800 (i don't now why )
(still without final commit or rollback to the main transaction)

==========

Connection #2:

START TRANSACTION;

INSERT INTO book (id, name)
VALUES (950, 'test_book_950');

=> will wait to the x lock release or it will return lock wait timeout 

========

Hi Mr. Zuhari,

Thank you very much for your bug report.

However, what you describe is expected behaviour.

Verbose InnoDB Status has all the information required that explains the behaviour.

Not a bug.

How was this expected behavior?
What is the idea of applying the next key lock in this case?

I didn't find anything related to this in the manual, can you give me a link to the manual on this case?

and again if i use RELEASE SAVEPOINT instead ROLLBACK TO SAVEPOINT the x lock will not applying, what the difference here between RELEASE and ROLLBACK ?

my question just why we applying next key lock when use ROLLBACK TO SAVEPOINT?

Hi,

InnoDB is a pessimistic ACID and MVCC storage engine. As such, it has some standards to follow, which it does.

We urge you once again to look at the full InnoDB status at various points in your transaction, because it explains properly what is going on ......

hey! 
i know whats is InnoDB, 

i checked  full InnoDB status again, i can't find anything useful, still i have the same question, the documentation have nothing about this behaviour!

i ready most of thing about locking, still confused why locking happening in this case!

here my InnoDB status:

=====================================
2023-02-10 20:20:23 0x700002b10000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 19 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 4 srv_active, 0 srv_shutdown, 95796 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 21
OS WAIT ARRAY INFO: signal count 20
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 287758
Purge done for trx's n:o < 287751 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422064157529552, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422064157528760, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422064157526384, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422064157525592, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 287757, ACTIVE 83 sec
1 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 10, OS thread handle 123145347465216, query id 140 localhost 127.0.0.1 mutaz starting
SHOW ENGINE INNODB STATUS
---TRANSACTION 287755, ACTIVE 154 sec
3 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 8, OS thread handle 123145345335296, query id 138 localhost 127.0.0.1 mutaz
Trx read view will not see trx with id >= 287755, sees < 287755
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
1367 OS file reads, 425 OS file writes, 141 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 3033, seg size 3035, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 5 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number          26792221390
Log buffer assigned up to    26792221390
Log buffer completed up to   26792221390
Log written up to            26792221390
Log flushed up to            26792221390
Added dirty pages up to      26792221390
Pages flushed up to          26792221390
Last checkpoint at           26792221390
Log minimum file id is       7981
Log maximum file id is       7981
35 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 517851
Buffer pool size   8192
Free buffers       6923
Database pages     1259
Old database pages 484
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1116, created 143, written 198
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1259, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=2985, Main thread ID=0x700001d55000 , state=sleeping
Number of rows inserted 1, updated 0, deleted 0, read 3
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 8, updated 329, deleted 8, read 8697
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Hi,

First of all, what you have sent us is not a full InnoDB status in the moment when next-key is applied.

Second, this is a forum for bug reports and not for asking questions.

Third, we maintain Reference Manual, but do not have User's Manual and the explanations that you are looking for much more appropriate for the Users Manual.