[MDEV-18429] Consistent non-locking reads do not appear in TRANSACTIONS section of SHOW ENGINE INNODB STATUS Created: 2019-01-30  Updated: 2020-08-25  Resolved: 2019-04-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.37, 10.2.20
Fix Version/s: 10.2.24, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: None

Issue Links:
Problem/Incident
causes MDEV-20675 Crash in SHOW ENGINE INNODB STATUS wi... Closed
Relates
relates to MDEV-17237 thread IDs are printed in different f... Open
relates to MDEV-17238 Document special thread IDs used in S... Open
relates to MDEV-18391 Print ENGINE INNODB STATUS in machine... Open
relates to MDEV-18572 Thread executing DROP TABLE listed tw... Open
relates to MDEV-18698 Show InnoDB's internal background thr... Open
relates to MDEV-21566 Lock monitor doesn't print a name for... Closed
relates to MDEV-22087 Increase buffer size for query in SHO... Open
relates to MDEV-18582 Port status variables related to SHOW... Closed
relates to MDEV-21330 Lock monitor doesn't print a semaphor... Closed
relates to MDEV-21390 lock_print_info_summary() should work... Closed

 Description   

Consistent non-locking reads are reads that do not require any locks because they read from a snapshot:

https://dev.mysql.com/doc/refman/5.7/en/innodb-consistent-read.html

These kinds of reads do not always appear in the TRANSACTIONS section of SHOW ENGINE INNODB STATUS. This might make sense if you don't really consider them transactions, because they don't require locks and they don't change any data.

However, if these reads run for a long time, then they can still affect things like undo logging and purge. I think it would make sense for these to appear in the TRANSACTIONS section of SHOW ENGINE INNODB STATUS.

For example, let's say that we create the following table:

CREATE TABLE tab (
   id int primary key,
   str varchar(50)
) ENGINE=InnoDB;
 
INSERT INTO tab VALUES
   (1, 'str1'),
   (2, 'str2'),
   (3, 'str3');

And then let's say that we execute the following query:

SELECT *, SLEEP(20) FROM tab;

In both MariaDB 10.1 and 10.2, if we execute SHOW ENGINE INNODB STATUS in another connection, then the SELECT does not appear in the TRANSACTIONS section. However, the ROW OPERATIONS section does show that the read view is open.

In MariaDB 10.2, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 5392
Purge done for trx's n:o < 5392 undo n:o < 0 state: running but idle
History list length 5
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421459782238616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421459782230168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=875, Main thread ID=139984359110400, state: sleeping
Number of rows inserted 3, updated 0, deleted 0, read 4
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.03 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

In MariaDB 10.2, the statement does not show up in the TRANSACTIONS section even if we explicitly start a transaction with START TRANSACTION first. e.g.:

START TRANSACTION;
SELECT *, SLEEP(20) FROM tab;

In MariaDB 10.2, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 5412
Purge done for trx's n:o < 5412 undo n:o < 0 state: running but idle
History list length 9
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421459782238616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421459782230168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=875, Main thread ID=139984359110400, state: sleeping
Number of rows inserted 5, updated 0, deleted 0, read 20
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.03 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

However, in MariaDB 10.1, the statement does show up in the TRANSACTIONS section if we explicitly start a transaction with START TRANSACTION first. e.g.:

START TRANSACTION;
SELECT *, SLEEP(20) FROM tab;

In MariaDB 10.1, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 22289
Purge done for trx's n:o < 22285 undo n:o < 0 state: running but idle
History list length 2
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 9, OS thread handle 0x7f5db4080f00, query id 22 localhost root Unlocking tables
SHOW ENGINE INNODB STATUS
---TRANSACTION 22275, not started
MySQL thread id 3, OS thread handle 0x7f5dd6983f00, query id 0 Waiting for background binlog tasks
---TRANSACTION 22288, ACTIVE 4 sec
mysql tables in use 1, locked 0
MySQL thread id 8, OS thread handle 0x7f5db40e3f00, query id 21 localhost root User sleep
SELECT *, SLEEP(20) FROM tab
Trx read view will not see trx with id >= 22289, sees < 22289
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
1 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
1 out of 1000 descriptors used
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 22289
Read view up limit trx id 22289
Read view low limit trx id 22289
Read view individually stored trx ids:
-----------------
Main thread process no. 3841, id 140039967192832, state: sleeping
Number of rows inserted 3, updated 0, deleted 0, read 10
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.04 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

In both MariaDB 10.1 and 10.2, the statement does show up if we change it to a SELECT FOR UPDATE. e.g.:

SELECT *, SLEEP(20) FROM tab FOR UPDATE;

In MariaDB 10.2, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 5393
Purge done for trx's n:o < 5392 undo n:o < 0 state: running but idle
History list length 5
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421459782238616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421459782230168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 5392, ACTIVE 4 sec
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 9, OS thread handle 139985073706752, query id 18 localhost root User sleep
SELECT *, SLEEP(20) FROM tab FOR UPDATE
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=875, Main thread ID=139984359110400, state: sleeping
Number of rows inserted 3, updated 0, deleted 0, read 7
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.02 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

In both MariaDB 10.1 and 10.2, the statement does show up if we write to the same table in the same transaction before selecting from it. e.g.:

START TRANSACTION;
INSERT INTO tab VALUES
   (4, 'str4');
SELECT *, SLEEP(20) FROM tab;

In MariaDB 10.2, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 5394
Purge done for trx's n:o < 5392 undo n:o < 0 state: running but idle
History list length 5
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421459782238616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421459782230168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 5393, ACTIVE 5 sec
mysql tables in use 1, locked 0
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 139985073706752, query id 22 localhost root User sleep
SELECT *, SLEEP(20) FROM tab
Trx read view will not see trx with id >= 5394, sees < 5394
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=875, Main thread ID=139984359110400, state: sleeping
Number of rows inserted 4, updated 0, deleted 0, read 10
0.03 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.03 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

In both MariaDB 10.1 and 10.2, the statement does show up if we write to a different table in the same transaction before selecting from it. e.g.:

CREATE TABLE tab2 LIKE tab;
START TRANSACTION;
INSERT INTO tab2 VALUES
   (4, 'str4');
SELECT *, SLEEP(20) FROM tab;

In MariaDB 10.2, the output looks like this in that case:

------------
TRANSACTIONS
------------
Trx id counter 5407
Purge done for trx's n:o < 5399 undo n:o < 0 state: running but idle
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421459782238616, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421459782230168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 5406, ACTIVE 6 sec
mysql tables in use 1, locked 0
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 139985073706752, query id 28 localhost root User sleep
SELECT *, SLEEP(20) FROM tab
Trx read view will not see trx with id >= 5407, sees < 5407
...
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=875, Main thread ID=139984359110400, state: sleeping
Number of rows inserted 5, updated 0, deleted 0, read 14
0.03 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.03 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s



 Comments   
Comment by Marko Mäkelä [ 2019-02-11 ]

A read view could also be created with the following statement:

START TRANSACTION WITH CONSISTENT SNAPSHOT;

Or you could have a multi-statement transaction.

In both cases, it is possible that there is no ‘current statement’. If the COMMIT or ROLLBACK never arrives, maybe because an interactive user forgot it, the read view would remain open and prevent the purge of old transaction history indefinitely.

For these cases, I believe that we should report the connection belonging to the read views, so that these views can be closed by the KILL statement.

Comment by Geoff Montee (Inactive) [ 2019-02-12 ]

If you spend any time fixing SHOW ENGINE INNODB STATUS output, it might also be worth making thread IDs consistent in the output at the same time. See MDEV-17237 for more information about that.

Comment by Geoff Montee (Inactive) [ 2019-02-14 ]

I also ran into another weird issue with the SHOW ENGINE INNODB STATUS output today. That one was submitted as MDEV-18572.

Comment by Marko Mäkelä [ 2019-04-29 ]

In the end, I had to rewrite kevg’s 10.2 fix after approving it, because due to MDEV-14756 and MDEV-15773, it was not straightforward to merge it to 10.3. The 10.3 version will simply traverse trx_sys.trx_list, and the 10.2 version mimics that.

Note that the omission was intentional. According to a source code comment, INFORMATION_SCHEMA.INNODB_TRX could be queried to find the missing transactions. I did not try to verify that claim.

Generated at Thu Feb 08 08:44:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.