Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.6.17, 10.11.7, 11.4.1
-
None
Description
When executing SHOW ENGINE INNODB STATUS, the output of the transaction lock wait timers is using ns as the suffix when us would be more appropriate given that the value seems very much like microseconds.
Here is an excerpt from two results that were taken one second apart.
------- TRX HAS BEEN WAITING 3608987 ns FOR THIS LOCK TO BE GRANTED:
|
------- TRX HAS BEEN WAITING 4609931 ns FOR THIS LOCK TO BE GRANTED:
|
If they were indeed nanoseconds, the value is about 1000 times too small.
MariaDB 10.5 seems to show the wait times in seconds which are accurate but in 10.6 the output is microseconds with a nanoseconds suffix.
Here is the test case that reproduces the "problem" and the full output of the commands.
MariaDB [(none)]> show engine innodb status\G do sleep(1); show engine innodb status\G
|
*************************** 1. row ***************************
|
Type: InnoDB
|
Name:
|
Status:
|
=====================================
|
2024-05-03 08:13:35 0x7f21d40d3640 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 22 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 8794 srv_idle
|
srv_master_thread log flush and writes: 8793
|
----------
|
SEMAPHORES
|
----------
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 745514
|
Purge done for trx's n:o < 745514 undo n:o < 0 state: running
|
History list length 2
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 745511, ACTIVE 12 sec
|
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
|
MariaDB thread id 254, OS thread handle 139783269512768, query id 30770 127.0.0.1 maxuser
|
---TRANSACTION 745508, ACTIVE 20 sec inserting
|
mysql tables in use 1, locked 1
|
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
|
MariaDB thread id 255, OS thread handle 139783268591168, query id 30771 127.0.0.1 maxuser Update
|
insert into t1 values (3, 0)
|
------- TRX HAS BEEN WAITING 3608987 ns FOR THIS LOCK TO BE GRANTED:
|
RECORD LOCKS space id 97 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 745508 lock mode S locks rec but not gap waiting
|
Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 4; hex 80000003; asc ;;
|
1: len 6; hex 0000000b6027; asc `';;
|
2: len 7; hex ae0000002e011c; asc . ;;
|
3: len 4; hex 80000000; asc ;;
|
|
|
------------------
|
---TRANSACTION (0x7f21bba00b80), not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync): 0
|
106327 OS file reads, 165 OS file writes, 39 OS fsyncs
|
0.00 reads/s, 0 avg bytes/read, 0.23 writes/s, 0.23 fsyncs/s
|
---
|
LOG
|
---
|
Log sequence number 7100269770
|
Log flushed up to 7100269770
|
Pages flushed up to 7100232444
|
Last checkpoint at 7100232428
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 2181038080
|
Dictionary memory allocated 13317440
|
Buffer pool size 129792
|
Free buffers 23739
|
Database pages 106053
|
Old database pages 39128
|
Modified db pages 44
|
Percent of dirty pages(LRU & free pages): 0.034
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 0, flush list 0
|
Pages made young 1868960, not young 3055336
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 106291, created 140, written 0
|
0.00 reads/s, 0.05 creates/s, 0.00 writes/s
|
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
|
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
|
LRU len: 106053, unzip_LRU len: 0
|
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
state: sleeping
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
|
1 row in set (0.000 sec)
|
|
|
Query OK, 0 rows affected (1.000 sec)
|
|
|
*************************** 1. row ***************************
|
Type: InnoDB
|
Name:
|
Status:
|
=====================================
|
2024-05-03 08:13:36 0x7f21cffb4640 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 1 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 8795 srv_idle
|
srv_master_thread log flush and writes: 8794
|
----------
|
SEMAPHORES
|
----------
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 745514
|
Purge done for trx's n:o < 745514 undo n:o < 0 state: running
|
History list length 2
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 745511, ACTIVE 13 sec
|
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
|
MariaDB thread id 254, OS thread handle 139783269512768, query id 30770 127.0.0.1 maxuser
|
---TRANSACTION 745508, ACTIVE 21 sec inserting
|
mysql tables in use 1, locked 1
|
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
|
MariaDB thread id 255, OS thread handle 139783268591168, query id 30771 127.0.0.1 maxuser Update
|
insert into t1 values (3, 0)
|
------- TRX HAS BEEN WAITING 4609931 ns FOR THIS LOCK TO BE GRANTED:
|
RECORD LOCKS space id 97 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 745508 lock mode S locks rec but not gap waiting
|
Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 4; hex 80000003; asc ;;
|
1: len 6; hex 0000000b6027; asc `';;
|
2: len 7; hex ae0000002e011c; asc . ;;
|
3: len 4; hex 80000000; asc ;;
|
|
|
------------------
|
---TRANSACTION (0x7f21bba00b80), not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync): 0
|
106327 OS file reads, 165 OS file writes, 39 OS fsyncs
|
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
---
|
LOG
|
---
|
Log sequence number 7100269770
|
Log flushed up to 7100269770
|
Pages flushed up to 7100232444
|
Last checkpoint at 7100232428
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 2181038080
|
Dictionary memory allocated 13317440
|
Buffer pool size 129792
|
Free buffers 23739
|
Database pages 106053
|
Old database pages 39128
|
Modified db pages 44
|
Percent of dirty pages(LRU & free pages): 0.034
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 0, flush list 0
|
Pages made young 1868960, not young 3055336
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 106291, created 140, written 0
|
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
|
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
|
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
|
LRU len: 106053, unzip_LRU len: 0
|
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
state: sleeping
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
|
1 row in set (0.001 sec)
|
Attachments
Issue Links
- is caused by
-
-
- Closed
-