|
another example
BACKGROUND THREAD
|
2-----------------
|
3srv_master_thread loops: 17 srv_active, 0 srv_shutdown, 76130 srv_idle
|
4srv_master_thread log flush and writes: 76123
|
5----------
|
6SEMAPHORES
|
7----------
|
8OS WAIT ARRAY INFO: reservation count 137
|
9--Thread 140027401070336 has waited at buf0buf.cc line 2709 for 3293.00 seconds the semaphore:
|
10S-lock on RW-latch at 0x7f5c0c0c8678 created in file buf0buf.cc line 1174
|
11a writer (thread id 0) has reserved it in mode exclusive
|
12number of readers 0, waiters flag 1, lock_word: 0
|
13Last time write locked in file buf0rea.cc line 120
|
14--Thread 140027493603072 has waited at btr0cur.cc line 6228 for 3293.00 seconds the semaphore:
|
15S-lock on RW-latch at 0x7f5c34148f78 created in file buf0buf.cc line 1174
|
16a writer (thread id 140027401070336) has reserved it in mode exclusive
|
17number of readers 0, waiters flag 1, lock_word: 0
|
18Last time write locked in file mtr0mtr.inl line 146
|
19OS WAIT ARRAY INFO: signal count 112
|
20RW-shared spins 105, rounds 3010, OS waits 89
|
21RW-excl spins 2, rounds 60, OS waits 1
|
22RW-sx spins 0, rounds 0, OS waits 0
|
23Spin rounds per wait: 28.67 RW-shared, 30.00 RW-excl, 0.00 RW-sx
|
24------------
|
25TRANSACTIONS
|
26------------
|
27Trx id counter 98383
|
28Purge done for trx's n:o < 98383 undo n:o < 0 state: running
|
29History list length 22
|
30LIST OF TRANSACTIONS FOR EACH SESSION:
|
31---TRANSACTION 421509506278704, ACTIVE 3293 sec estimating records in index range
|
32mysql tables in use 6, locked 0
|
330 lock struct(s), heap size 1128, 0 row lock(s)
|
34MySQL thread id 893, OS thread handle 140027493603072, query id 8597 localhost dev Statistics
|
35SELECT `thing`.`id`, `thing`.`id_account`, `thing`.`id_something2`, `thing`.`id_something2_link`, IFNULL((
|
36 SELECT SUM(ct1.amount)
|
37 FROM thing_transaction ct1
|
38 WHERE ct1.status = "success"
|
39 AND ct1.type = "thing"
|
40 AND ct1.id_thing = thing.id), 0) -
|
41 IFNULL((
|
42 SELECT SUM(ct2.amount)
|
43 FROM thing_transaction ct2
|
44 WHERE ct2.status = "success"
|
45 AND ct2.type = "chargeback"
|
46 AND ct2.id_thing = comm
|
47Trx read view will not see trx with id >= 98383, sees < 98383
|
48---TRANSACTION 421509506248912, not started
|
490 lock struct(s), heap size 1128, 0 row lock(s)
|
50--------
|
51FILE I/O
|
52--------
|
53Pending flushes (fsync) log: 0; buffer pool: 0
|
5443270 OS file reads, 705 OS file writes, 374 OS fsyncs
|
55-0.00 reads/s, 12873 avg bytes/read, -0.00 writes/s, -0.00 fsyncs/s
|
56-------------------------------------
|
57INSERT BUFFER AND ADAPTIVE HASH INDEX
|
58-------------------------------------
|
59Ibuf: size 1, free list len 48012, seg size 48014, 0 merges
|
60merged operations:
|
61 insert 0, delete mark 0, delete 0
|
62discarded operations:
|
63 insert 0, delete mark 0, delete 0
|
64-0.00 hash searches/s, -0.02 non-hash searches/s
|
65---
|
66LOG
|
|
|
|
these queries all worked fine in 10.1 and have become issues in 10.1
MariaDB [(none)]> \s
|
--------------
|
mysql Ver 15.1 Distrib 10.1.48-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
|
|
Connection id: 6264
|
Current database:
|
Current user: root@localhost
|
SSL: Cipher in use is DHE-RSA-AES256-GCM-SHA384
|
Current pager: stdout
|
Using outfile: ''
|
Using delimiter: ;
|
Server: MariaDB
|
Server version: 10.1.48-MariaDB-1~bionic mariadb.org binary distribution
|
Protocol version: 10
|
Connection: Localhost via UNIX socket
|
Server characterset: latin1
|
Db characterset: latin1
|
Client characterset: utf8
|
Conn. characterset: utf8
|
UNIX socket: /var/run/mysqld/mysqld.sock
|
Uptime: 2 days 1 hour 33 min 33 sec
|
|
Threads: 1 Questions: 73248 Slow queries: 380 Opens: 247 Flush tables: 1 Open tables: 239 Queries per second avg: 0.410
|
--------------
|
|
MariaDB [(none)]>
|
|
|
Given "ACTIVE 17091 sec" kinds of output, could it be that there has been a serious degradation of the query plan of some of these queries?
Take a look at EXPLAIN EXTENDED query plans on both servers.
|
|
on 10. 5
explain extended
|
active lock
|
|
| InnoDB | |
|
=====================================
|
2022-08-24 14:30:18 0x7f8d3eafd700 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 18446744073709217795 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 31 srv_active, 0 srv_shutdown, 990506 srv_idle
|
srv_master_thread log flush and writes: 990414
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 79
|
--Thread 140244446332672 has waited at buf0buf.cc line 2709 for 11767.00 seconds the semaphore:
|
S-lock on RW-latch at 0x7f8cec1ce878 created in file buf0buf.cc line 1174
|
a writer (thread id 0) has reserved it in mode exclusive
|
number of readers 0, waiters flag 1, lock_word: 0
|
Last time write locked in file buf0rea.cc line 120
|
OS WAIT ARRAY INFO: signal count 49
|
RW-shared spins 19, rounds 493, OS waits 16
|
RW-excl spins 0, rounds 0, OS waits 0
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 25.95 RW-shared, 0.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 104366
|
Purge done for trx's n:o < 104355 undo n:o < 0 state: running
|
History list length 15
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 421719424282992, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
---TRANSACTION 104365, ACTIVE 11767 sec updating or deleting
|
mysql tables in use 1, locked 1
|
2 lock struct(s), heap size 1128, 1 row lock(s)
|
MySQL thread id 77016, OS thread handle 140244446332672, query id 247676 localhost dev Updating
|
UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('4538127'))
|
---TRANSACTION 421719424278736, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
47773 OS file reads, 592 OS file writes, 602 OS fsyncs
|
-0.00 reads/s, 12288 avg bytes/read, -0.00 writes/s, -0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 48012, seg size 48014, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
-0.00 hash searches/s, -0.01 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 191344802500
|
Log flushed up to 191344802442
|
Pages flushed up to 191344318870
|
Last checkpoint at 191344318858
|
0 pending log flushes, 0 pending chkp writes
|
594 log i/o's done, 44.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 21357395968
|
Dictionary memory allocated 127186560
|
Buffer pool size 1282335
|
Free buffers 1234609
|
Database pages 47726
|
Old database pages 17637
|
Modified db pages 597
|
Percent of dirty pages(LRU & free pages): 0.047
|
Max dirty pages percent: 90.000
|
Pending reads 1
|
Pending writes: LRU 0, flush list 0
|
Pages made young 2, not young 0
|
-0.00 youngs/s, -0.00 non-youngs/s
|
Pages read 47562, created 159, written 0
|
-0.00 reads/s, -0.00 creates/s, -0.00 writes/s
|
Buffer pool hit rate 999 / 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: 47726, unzip_LRU len: 0
|
I/O sum[0]:cur[3], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 278, updated 248, deleted 87, read 69830122
|
-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
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
|
|
MariaDB [dev]> explain extended UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('4532281217'));
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| 1 | SIMPLE | thing_transaction | range | PRIMARY | PRIMARY | 4 | NULL | 1 | 100.00 | Using where |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
1 row in set (0.000 sec)
|
|
MariaDB [dev]>
|
on 10.1
Database changed
|
MariaDB [dev]> explain extended UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('4532281217'));
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| 1 | SIMPLE | thing_transaction | range | PRIMARY | PRIMARY | 4 | NULL | 1 | 100.00 | Using where |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [dev]> \s
|
--------------
|
|
|
on 10. 5
explain extended
|
active lock
|
|
| InnoDB | |
|
=====================================
|
2022-08-24 14:30:18 0x7f8d3eafd700 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 18446744073709217795 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 31 srv_active, 0 srv_shutdown, 990506 srv_idle
|
srv_master_thread log flush and writes: 990414
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 79
|
--Thread 140244446332672 has waited at buf0buf.cc line 2709 for 11767.00 seconds the semaphore:
|
S-lock on RW-latch at 0x7f8cec1ce878 created in file buf0buf.cc line 1174
|
a writer (thread id 0) has reserved it in mode exclusive
|
number of readers 0, waiters flag 1, lock_word: 0
|
Last time write locked in file buf0rea.cc line 120
|
OS WAIT ARRAY INFO: signal count 49
|
RW-shared spins 19, rounds 493, OS waits 16
|
RW-excl spins 0, rounds 0, OS waits 0
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 25.95 RW-shared, 0.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 104366
|
Purge done for trx's n:o < 104355 undo n:o < 0 state: running
|
History list length 15
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 421719424282992, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
---TRANSACTION 104365, ACTIVE 11767 sec updating or deleting
|
mysql tables in use 1, locked 1
|
2 lock struct(s), heap size 1128, 1 row lock(s)
|
MySQL thread id 77016, OS thread handle 140244446332672, query id 247676 localhost dev Updating
|
UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('42343243'))
|
---TRANSACTION 421719424278736, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
47773 OS file reads, 592 OS file writes, 602 OS fsyncs
|
-0.00 reads/s, 12288 avg bytes/read, -0.00 writes/s, -0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 48012, seg size 48014, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
-0.00 hash searches/s, -0.01 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 191344802500
|
Log flushed up to 191344802442
|
Pages flushed up to 191344318870
|
Last checkpoint at 191344318858
|
0 pending log flushes, 0 pending chkp writes
|
594 log i/o's done, 44.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 21357395968
|
Dictionary memory allocated 127186560
|
Buffer pool size 1282335
|
Free buffers 1234609
|
Database pages 47726
|
Old database pages 17637
|
Modified db pages 597
|
Percent of dirty pages(LRU & free pages): 0.047
|
Max dirty pages percent: 90.000
|
Pending reads 1
|
Pending writes: LRU 0, flush list 0
|
Pages made young 2, not young 0
|
-0.00 youngs/s, -0.00 non-youngs/s
|
Pages read 47562, created 159, written 0
|
-0.00 reads/s, -0.00 creates/s, -0.00 writes/s
|
Buffer pool hit rate 999 / 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: 47726, unzip_LRU len: 0
|
I/O sum[0]:cur[3], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 278, updated 248, deleted 87, read 69830122
|
-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
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
|
|
MariaDB [dev]> explain extended UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('42343243'));
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| 1 | SIMPLE | thing_transaction | range | PRIMARY | PRIMARY | 4 | NULL | 1 | 100.00 | Using where |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
1 row in set (0.000 sec)
|
|
MariaDB [dev]>
|
on 10.1
Database changed
|
MariaDB [dev]> explain extended UPDATE `thing_transaction` SET `id_ach` = '768768978978978', `status` = 'success', `last_updated` = '2022-08-24 11:14:11', `paid_on` = CURDATE() WHERE (id IN ('42343243'));
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
| 1 | SIMPLE | thing_transaction | range | PRIMARY | PRIMARY | 4 | NULL | 1 | 100.00 | Using where |
|
+------+-------------+------------------------+-------+---------------+---------+---------+------+------+----------+-------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [dev]> \s
|
--------------
|
|
|
hello any updates here?
|
|
stackoverdrive, without knowing the table schema or the configuration parameters, only guesses are possible. One guess would be that the long-deprecated option innodb_locks_unsafe_for_binlog (MDEV-19563) will be ignored starting with MariaDB Server 10.5. Maybe cvicentiu and serg should not have introduced the MARIADB_REMOVED_OPTION to allow an upgraded server to start up without forcing the DBA to review the configuration parameters.
An alternative of using SET TRANSACTION ISOLATION LEVEL READ COMMITTED was introduced for the option innodb_locks_unsafe_for_binlog a long time ago. Which transaction isolation level are you using?
|
|
we have made the suggested change and are seeing locks
| InnoDB | |
|
=====================================
|
2022-09-26 13:02:59 0x7f1445fa0700 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 18446744073706361222 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 29 srv_active, 0 srv_shutdown, 1757 srv_idle
|
srv_master_thread log flush and writes: 1775
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 79
|
--Thread 139724550096640 has waited at buf0buf.cc line 2581 for 6515.00 seconds the semaphore:
|
S-lock on RW-latch at 0x7f13f40d7e78 created in file buf0buf.cc line 1046
|
a writer (thread id 0) has reserved it in mode exclusive
|
number of readers 0, waiters flag 1, lock_word: 0
|
Last time write locked in file buf0rea.cc line 120
|
OS WAIT ARRAY INFO: signal count 64
|
RW-shared spins 119, rounds 2489, OS waits 43
|
RW-excl spins 3, rounds 90, OS waits 3
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 20.92 RW-shared, 30.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 99731
|
Purge done for trx's n:o < 99725 undo n:o < 0 state: running
|
History list length 11
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 421199550197968, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
---TRANSACTION 99730, ACTIVE 6142 sec starting index read
|
mysql tables in use 1, locked 1
|
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
|
MySQL thread id 693, OS thread handle 139724550403840, query id 8855 localhost dev Updating
|
UPDATE `account_transaction` SET `bank_account_number` = '121212121212', `bank_routing_number` = '12121212', `bank_account_type` = 'Checking' WHERE (`account_transaction`.`id` = 12121212)
|
------- TRX HAS BEEN WAITING 6142 SEC FOR THIS LOCK TO BE GRANTED:
|
RECORD LOCKS space id 356 page no 529847 n bits 200 index PRIMARY of table `dev`.`account_transaction` trx id 99730 lock_mode X locks rec but not gap waiting
|
Record lock, heap no 127 PHYSICAL RECORD: n_fields 37; compact format; info bits 0
|
0: len 4; hex 041d237b; asc #{;;
|
1: len 6; hex 000000018591; asc ;;
|
2: len 7; hex 65000200241aae; asc e $ ;;
|
3: len 3; hex 0b9bbd; asc ;;
|
4: len 4; hex 00000000; asc ;;
|
5: len 1; hex 01; asc ;;
|
6: len 5; hex 8000008a00; asc ;;
|
7: len 1; hex 01; asc ;;
|
8: SQL NULL;
|
9: len 0; hex ; asc ;;
|
10: len 3; hex 000000; asc ;;
|
11: len 0; hex ; asc ;;
|
12: len 0; hex ; asc ;;
|
13: len 0; hex ; asc ;;
|
14: len 1; hex 01; asc ;;
|
15: len 0; hex ; asc ;;
|
16: len 0; hex ; asc ;;
|
17: SQL NULL;
|
18: len 0; hex ; asc ;;
|
19: SQL NULL;
|
20: len 0; hex ; asc ;;
|
21: len 3; hex 8fcd26; asc &;;
|
22: len 3; hex 800000; asc ;;
|
23: len 5; hex 99adf4b398; asc ;;
|
24: len 5; hex 3030303233; asc 00023;;
|
25: len 30; hex 53706563696669656420736f75726365206b6579206e6f7420666f756e64; asc Specified source key not found; (total 31 bytes);
|
26: len 1; hex 04; asc ;;
|
27: len 1; hex 80; asc ;;
|
28: len 1; hex 00; asc ;;
|
29: len 5; hex 8000000032; asc 2;;
|
30: len 1; hex 00; asc ;;
|
31: len 5; hex 99ad7aa60b; asc z ;;
|
32: len 3; hex 005bcb; asc [ ;;
|
33: len 5; hex 99ad7aa60b; asc z ;;
|
34: len 3; hex 005bcb; asc [ ;;
|
35: len 1; hex 80; asc ;;
|
36: len 1; hex 80; asc ;;
|
|
------------------
|
---TRANSACTION 99729, ACTIVE 6515 sec updating or deleting
|
mysql tables in use 1, locked 1
|
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
|
MySQL thread id 539, OS thread handle 139724550096640, query id 7881 localhost dev Updating
|
UPDATE `account_transaction` SET `status` = 'failure', `failure_date` = NOW(), `failure_description` = 'Specified source key not found.', `failure_code` = '0000' WHERE (id = 12121212)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
43732 OS file reads, 281 OS file writes, 463 OS fsyncs
|
-0.00 reads/s, 10922 avg bytes/read, -0.00 writes/s, -0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 48011, seg size 48013, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
-0.00 hash searches/s, -0.00 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 197107157970
|
Log flushed up to 197107157672
|
Pages flushed up to 197105764376
|
Last checkpoint at 197105764364
|
0 pending log flushes, 0 pending chkp writes
|
280 log i/o's done, 11.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 6459228160
|
Dictionary memory allocated 38736792
|
Buffer pool size 387120
|
Free buffers 343337
|
Database pages 43783
|
Old database pages 16182
|
Modified db pages 866
|
Percent of dirty pages(LRU & free pages): 0.224
|
Max dirty pages percent: 90.000
|
Pending reads 2
|
Pending writes: LRU 0, flush list 0
|
Pages made young 8, not young 0
|
-0.00 youngs/s, -0.00 non-youngs/s
|
Pages read 43527, created 254, written 0
|
-0.00 reads/s, -0.00 creates/s, -0.00 writes/s
|
Buffer pool hit rate 993 / 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: 43783, unzip_LRU len: 0
|
I/O sum[0]:cur[16], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 130, updated 82, deleted 50, read 16125838
|
-0.00 inserts/s, -0.00 updates/s, -0.00 deletes/s, -0.00 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
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
table schema
MariaDB [dev]> describe account_transaction;
|
+---------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+-----+---------+----------------+
|
| Field | Type | Null | Key | Default | Extra |
|
+---------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+-----+---------+----------------+
|
| id | int(11) unsigned | NO | PRI | NULL | auto_increment |
|
| id_account | mediumint(8) unsigned | NO | MUL | NULL | |
|
| id_account_payment | int(10) unsigned | NO | MUL | NULL | |
|
| type | enum('debit','special_debit','nsf_fee','cancel_fee','refund','loan_payment','over_phone_loan_payment','single_loan_payment','accelerated_loan_payment','enrollment_fee','credit','fee_loan_payment','charged_off','charged_off_credit','collection','positive_balance_adjustment','negative_balance_adjustment','stop_payment_fee') | YES | MUL | NULL | |
|
| amount | decimal(10,2) | NO | | NULL | |
|
| owner | enum('smart','debtwave','msb') | NO | MUL | smart | |
|
| processor | varchar(20) | YES | MUL | NULL | |
|
| id_ach | varchar(32) | NO | MUL | NULL | |
|
| id_lender | mediumint(8) unsigned | NO | | NULL | |
|
| lender | varchar(32) | NO | | NULL | |
|
| bank_account_number | varchar(32) | NO | | NULL | |
|
| bank_routing_number | varchar(32) | NO | | NULL | |
|
| bank_account_type | enum('Checking','Savings','Money Market','Other','Corporate','Corporate Savings') | NO | | NULL | |
|
| gtb_payment_desc | varchar(64) | NO | | NULL | |
|
| loan_account_number | varchar(32) | NO | | NULL | |
|
| id_account_check_statuses | int(11) | YES | MUL | NULL | |
|
| check_number | varchar(32) | NO | MUL | NULL | |
|
| cleared_date | date | YES | | NULL | |
|
| reason | text | NO | | NULL | |
|
| scheduled_on | date | NO | MUL | NULL | |
|
| paid_on | date | NO | MUL | NULL | |
|
| failure_date | datetime | NO | | NULL | |
|
| failure_code | char(5) | NO | | NULL | |
|
| failure_description | text | NO | | NULL | |
|
| status | enum('pending','canceled','success','failure','processing') | NO | | NULL | |
|
| processed_externally | tinyint(1) | NO | | 0 | |
|
| on_hold | tinyint(3) unsigned | NO | | NULL | |
|
| fee | decimal(10,2) | NO | | NULL | |
|
| recollection | tinyint(3) unsigned | NO | | 0 | |
|
| created_on | datetime | NO | | NULL | |
|
| created_on_by | mediumint(8) unsigned | NO | | NULL | |
|
| last_updated | datetime | NO | | NULL | |
|
| last_updated_by | mediumint(8) unsigned | NO | | NULL | |
|
| auto_updated | tinyint(1) | NO | | 0 | |
|
| force_check | tinyint(1) | NO | | 0 | |
|
+---------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+-----+---------+----------------+
|
35 rows in set (0.002 sec)
|
|
MariaDB [dev]>
|
|
MariaDB [dev]> show variables like '%isolation%';
|
+---------------+-----------------+
|
| Variable_name | Value |
|
+---------------+-----------------+
|
| tx_isolation | REPEATABLE-READ |
|
+---------------+-----------------+
|
1 row in set (0.002 sec)
|
|
MariaDB [dev]>
|
MariaDB [dev]> explain UPDATE `account_transaction` SET `status` = 'failure', `failure_date` = NOW(), `failure_description` = 'Specified source key not found.', `failure_code` = '0000' WHERE (id = 12121212)
|
-> ;
|
+------+-------------+---------------------+-------+---------------+---------+---------+------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+---------------------+-------+---------------+---------+---------+------+------+-------------+
|
| 1 | SIMPLE | account_transaction | range | PRIMARY | PRIMARY | 4 | NULL | 1 | Using where |
|
+------+-------------+---------------------+-------+---------------+---------+---------+------+------+-------------+
|
1 row in set (0.001 sec)
|
|
MariaDB [dev]>
|
|
|
more details
MariaDB [(none)]> show full processlist \G
|
*************************** 1. row ***************************
|
Id: 1010
|
User: dev
|
Host: localhost
|
db: dev
|
Command: Query
|
Time: 14212
|
State: Sending data
|
Info: SELECT `commission`.`id`, `commission`.`id_account`, `commission`.`id_partner`, `commission`.`id_partner_link`, IFNULL((
|
SELECT SUM(ct1.amount)
|
FROM commission_transaction ct1
|
WHERE ct1.status = "success"
|
AND ct1.type = "payment"
|
AND ct1.id_commission = commission.id), 0) -
|
IFNULL((
|
SELECT SUM(ct2.amount)
|
FROM commission_transaction ct2
|
WHERE ct2.status = "success"
|
AND ct2.type = "chargeback"
|
AND ct2.id_commission = commission.id), 0) AS `PaidSum`, IFNULL((
|
SELECT SUM(ct3.amount)
|
FROM commission_transaction ct3
|
WHERE ct3.status = "pending"
|
AND ct3.type = "payment"
|
AND ct3.id_commission = commission.id), 0) -
|
IFNULL((
|
SELECT SUM(ct4.amount)
|
FROM commission_transaction ct4
|
WHERE ct4.status = "pending"
|
AND ct4.type = "chargeback"
|
AND ct4.id_commission = commission.id), 0) AS `PendingSum`, IFNULL((
|
SELECT SUM(cs1.amount)
|
FROM commission_structure cs1
|
WHERE cs1.disable = 0
|
AND cs1.id_commission = commission.id), 0) AS `CommissionOwed` FROM `commission` WHERE (commission.id_account = '121212')
|
Progress: 0.000
|
*************************** 2. row ***************************
|
Id: 1083
|
User: root
|
Host: localhost
|
db: NULL
|
Command: Query
|
Time: 0
|
State: starting
|
Info: show full processlist
|
Progress: 0.000
|
2 rows in set (0.000 sec)
|
|
MariaDB [(none)]> show engine innodb status \G
|
*************************** 1. row ***************************
|
Type: InnoDB
|
Name:
|
Status:
|
=====================================
|
2022-09-13 08:44:05 0x7f59541c5700 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 71 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 62093 srv_idle
|
srv_master_thread log flush and writes: 62060
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 19
|
--Thread 140021828638464 has waited at row0sel.cc line 4719 for 14172.00 seconds the semaphore:
|
S-lock on RW-latch at 0x7f593407c078 created in file buf0buf.cc line 1046
|
a writer (thread id 140014612133632) has reserved it in mode exclusive
|
number of readers 0, waiters flag 1, lock_word: 0
|
Last time write locked in file mtr0mtr.inl line 146
|
--Thread 140014612133632 has waited at buf0buf.cc line 2581 for 14172.00 seconds the semaphore:
|
S-lock on RW-latch at 0x7f5934082078 created in file buf0buf.cc line 1046
|
a writer (thread id 0) has reserved it in mode exclusive
|
number of readers 0, waiters flag 1, lock_word: 0
|
Last time write locked in file buf0rea.cc line 120
|
OS WAIT ARRAY INFO: signal count 8
|
RW-shared spins 3, rounds 30, OS waits 1
|
RW-excl spins 0, rounds 0, OS waits 0
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 10.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 99819
|
Purge done for trx's n:o < 99804 undo n:o < 0 state: running
|
History list length 12
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 421496633812272, ACTIVE 14172 sec starting index read
|
mysql tables in use 6, locked 0
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
MySQL thread id 1010, OS thread handle 140021828638464, query id 3652 localhost dev Sending data
|
SELECT `commission`.`id`, `commission`.`id_account`, `commission`.`id_partner`, `commission`.`id_partner_link`, IFNULL((
|
SELECT SUM(ct1.amount)
|
FROM commission_transaction ct1
|
WHERE ct1.status = "success"
|
AND ct1.type = "payment"
|
AND ct1.id_commission = commission.id), 0) -
|
IFNULL((
|
SELECT SUM(ct2.amount)
|
FROM commission_transaction ct2
|
WHERE ct2.status = "success"
|
AND ct2.type = "chargeback"
|
AND ct2.id_commission = comm
|
Trx read view will not see trx with id >= 99817, sees < 99817
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
25351 OS file reads, 23 OS file writes, 23 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 48011, seg size 48013, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
0.00 hash searches/s, 0.00 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 197107173630
|
Log flushed up to 197107173630
|
Pages flushed up to 197107159144
|
Last checkpoint at 197107159132
|
0 pending log flushes, 0 pending chkp writes
|
25 log i/o's done, 0.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 6459228160
|
Dictionary memory allocated 38445912
|
Buffer pool size 387120
|
Free buffers 361723
|
Database pages 25397
|
Old database pages 9395
|
Modified db pages 133
|
Percent of dirty pages(LRU & free pages): 0.034
|
Max dirty pages percent: 90.000
|
Pending reads 1
|
Pending writes: LRU 0, flush list 0
|
Pages made young 0, not young 0
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 25264, created 132, written 0
|
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: 25397, unzip_LRU len: 0
|
I/O sum[0]:cur[24266], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
1 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 15, updated 5, deleted 1, read 7524234
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 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
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
1 row in set (0.001 sec)
|
|
|
Sorry, I had forgotten this ticket for a while, and found it accidentally now.
It is unclear which suggested change you are referring to. In any case, it looks like there is a lock conflict on a PRIMARY KEY record itself, not on any gap locks (which would not be acquired when using the READ COMMITTED isolation level):
---TRANSACTION 99730, ACTIVE 6142 sec starting index read
|
mysql tables in use 1, locked 1
|
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
|
MySQL thread id 693, OS thread handle 139724550403840, query id 8855 localhost dev Updating
|
UPDATE `account_transaction` SET `bank_account_number` = '121212121212', `bank_routing_number` = '12121212', `bank_account_type` = 'Checking' WHERE (`account_transaction`.`id` = 12121212)
|
------- TRX HAS BEEN WAITING 6142 SEC FOR THIS LOCK TO BE GRANTED:
|
RECORD LOCKS space id 356 page no 529847 n bits 200 index PRIMARY of table `dev`.`account_transaction` trx id 99730 lock_mode X locks rec but not gap waiting
|
Record lock, heap no 127 PHYSICAL RECORD: n_fields 37; compact format; info bits 0
|
0: len 4; hex 041d237b; asc #{;;
|
1: len 6; hex 000000018591; asc ;;
|
2: len 7; hex 65000200241aae; asc e $ ;;
|
3: len 3; hex 0b9bbd; asc ;;
|
…
|
The actual primary key is 0x041d237b = 69018491. This record is not delete-marked (info bits 0) and I suppose that it could be implicitly locked by the transaction 0x18591 = 99729 (exactly one transaction right before the current one, which is 99730) which had updated or delete-unmarked the record (the most significant bit of the 7-byte DB_ROLL_PTR is clear). A number of transactions have been started since then:
Trx id counter 99819
|
Purge done for trx's n:o < 99804 undo n:o < 0 state: running
|
That the purge of committed transaction history was able to advance beyond 99729 looks very strange. Also the following looks strange:
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 421496633812272, ACTIVE 14172 sec starting index read
|
That large number is 0x17F595521E530 in hexadecimal. I checked the code in trx_print_low():
if (const trx_id_t id = trx->id) {
|
fprintf(f, "TRANSACTION " TRX_ID_FMT, trx->id);
|
} else {
|
fprintf(f, "TRANSACTION (%p)", trx);
|
}
|
So, the print-out really is of a trx->id, and not the memory pointer of a read-only transaction (which should not acquire any locks in the first place).
Because the field DB_TRX_ID is only 48 bits (6 bytes, 12 hexadecimal digits), this transaction identifier (13 hexadecimal digits) is invalid. In some other places, InnoDB reserves 64 bits (8 bytes) for the transaction ID. This strongly looks like a duplicate of MDEV-27800, or something related.
The only thing that bothers me is that you report that this occurred on an upgrade from 10.1 to 10.5.16, and MDEV-27800 was supposed to be fixed in that version. Maybe I have missed something else, or you in fact had attempted an upgrade to some other MariaDB version that is later than 10.1 but older than 10.5.16.
The easiest fix of this corruption is to perform a logical dump and restore of the database, loading it to a newly initialized server. That would also give you benefits of the 10.5 default innodb_file_format=full_crc32 format (MDEV-19534).
|
|
Did you ever attempt an upgrade from 10.1 to older MariaDB version than 10.5.16? If yes, that could have caused some uninitialized data to be misinterpreted as real transaction identifiers. If not, then there apparently the fix of MDEV-27800 was incomplete, and we would need a copy of the 10.1 data directory (before any upgrade) to fix it.
Also, a last question: Was the database originally created with a very old version of MariaDB or MySQL? Quoting from MDEV-27800:
Unfortunately, before MySQL 5.1.48 and MariaDB 5.1.48, InnoDB did not always initialize data fields. The TRX_NO field in undo log pages could actually contain garbage, instead of 0.
|