[MDEV-33798] ROW base optimistic deadlock with concurrent writes on same table row and multi domain - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.11.7
Fix Version/s: 10.11.8, 10.6.18, 11.0.6, 11.1.5, 11.2.4, 11.4.2
Component/s: Replication
Labels:
None

Description

Issue:
Replication sql thread stopped in optimistic but ok in conservative

Context:
Concurrent writes on 2 tables with same name but different DB

Workaround
Moving to conservative fixed the replication sql thread regular stop

select * from api_check;

+----+---------------------+

| id | last_check |

+----+---------------------+

| 1 | 2024-03-29 09:49:10 |

+----+---------------------+

1 row in set (0.001 sec)

MariaDB [mixr_user]> show create table api_check;

+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

| Table | Create Table |

+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

| api_check | CREATE TABLE api_check (

id tinyint(3) unsigned NOT NULL,

last_check datetime NOT NULL DEFAULT '0000-00-00 00:00:00',

PRIMARY KEY (id)

) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci |

+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

1 row in set (0.000 sec)

Processlist:

| 3455587 | system user | | wpmixrgen | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:28' where id = 1 | 0.000 |

| 3455588 | system user | | mixr_user | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:27' where id = 1 | 0.000 |

No views in the middle

MariaDB [wpmixrgen]> show full tables like 'api_check';

+---------------------------------+------------+

| Tables_in_wpmixrgen (api_check) | Table_type |

+---------------------------------+------------+

| api_check                       | BASE TABLE |

+---------------------------------+------------+

1 row in set (0.002 sec)

Database changed

MariaDB [mixr_user]> show full tables like 'api_check';

+---------------------------------+------------+

| Tables_in_mixr_user (api_check) | Table_type |

+---------------------------------+------------+

| api_check                       | BASE TABLE |

+---------------------------------+------------+

1 row in set (0.001 sec)

Bonus:
Stop all slaves could stale when in such deadlock

| 3460647 | root | 10.48.0.1:55828 | NULL | Killed | 186 | Killing slave | stop all slaves

Metadata lock state:

+-----------+----------------------+---------------+---------------------+--------------+----------------+

| THREAD_ID | LOCK_MODE | LOCK_DURATION | LOCK_TYPE | TABLE_SCHEMA | TABLE_NAME |

+-----------+----------------------+---------------+---------------------+--------------+----------------+

| 3470443 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |

| 3470438 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |

| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |

| 3470438 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |

| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |

| 3470443 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |

| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |

| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |

| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |

| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | schedule_log |

+-----------+----------------------+---------------+---------------------+--------------+----------------+

10 rows in set (0.001 sec)

INNODB_TRX:

trx_id: 2669046603

trx_state: LOCK WAIT

trx_started: 2024-03-29 15:48:18

trx_requested_lock_id: 2669046603:27938:3:2

trx_wait_started: 2024-03-29 15:48:18

trx_weight: 2

trx_mysql_thread_id: 3470443

trx_query: update api_check set last_check = '2024-03-29 04:44:09' where id = 1

trx_operation_state: starting index read

trx_tables_in_use: 1

trx_tables_locked: 1

trx_lock_structs: 2

trx_lock_memory_bytes: 1128

trx_rows_locked: 1

trx_rows_modified: 0

trx_concurrency_tickets: 0

trx_isolation_level: REPEATABLE READ

trx_unique_checks: 1

trx_foreign_key_checks: 1

trx_last_foreign_key_error: NULL

trx_is_read_only: 0

trx_autocommit_non_locking: 0

---

trx_id: 2669046602

                 trx_state: LOCK WAIT

               trx_started: 2024-03-29 15:48:18

     trx_requested_lock_id: 2669046602:27887:3:2

          trx_wait_started: 2024-03-29 15:48:18

                trx_weight: 2

       trx_mysql_thread_id: 3470438

                 trx_query: update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1

       trx_operation_state: starting index read

         trx_tables_in_use: 1

         trx_tables_locked: 1

          trx_lock_structs: 2

     trx_lock_memory_bytes: 1128

           trx_rows_locked: 1

         trx_rows_modified: 0

   trx_concurrency_tickets: 0

       trx_isolation_level: REPEATABLE READ

         trx_unique_checks: 1

    trx_foreign_key_checks: 1

trx_last_foreign_key_error: NULL

          trx_is_read_only: 0

trx_autocommit_non_locking: 0

InnoDB Status:

MariaDB [information_schema]> show engine innodb status\G

*************************** 1. row ***************************

  Type: InnoDB

  Name:

Status:

=====================================

2024-03-29 15:51:38 0x7f696c107640 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 1 seconds

-----------------

BACKGROUND THREAD

-----------------

srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 3704919 srv_idle

srv_master_thread log flush and writes: 3704803

----------

SEMAPHORES

----------

------------

TRANSACTIONS

------------

Trx id counter 2669046610

Purge done for trx's n:o < 2669046590 undo n:o < 0 state: running

History list length 2

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 2669046609, ACTIVE 50 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)

MariaDB thread id 3470438, OS thread handle 140090653918784, query id 380459332 Update_rows_log_event::find_row(-1) on table `api_check`

update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1

------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 27887 page no 3 n bits 8 index PRIMARY of table `mixr_user`.`api_check` trx id 2669046609 lock_mode X locks rec but not gap waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0

 0: len 1; hex 01; asc  ;;

 1: len 6; hex 00009f166b2e; asc     k.;;

 2: len 7; hex 350000c0030110; asc 5      ;;

 3: len 5; hex 99b2fa4b0e; asc    K ;;

------------------

---TRANSACTION (0x7f6aa4544380), not started

0 lock struct(s), heap size 1128, 0 row lock(s)

---TRANSACTION (0x7f6aa4543880), not started

0 lock struct(s), heap size 1128, 0 row lock(s)

---TRANSACTION (0x7f6aa4542d80), not started

0 lock struct(s), heap size 1128, 0 row lock(s)

---TRANSACTION 2669046575, ACTIVE (PREPARED) 550 sec

3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2

MariaDB thread id 3470442, OS thread handle 140090649925184, query id 380457775 Waiting for prior transaction to commit

---TRANSACTION 2669046608, ACTIVE 50 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)

MariaDB thread id 3470443, OS thread handle 140090649310784, query id 380459331 Update_rows_log_event::find_row(-1) on table `api_check`

update `api_check` set `last_check` = '2024-03-29 04:44:09' where `id` = 1

------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 27938 page no 3 n bits 8 index PRIMARY of table `wpmixrgen`.`api_check` trx id 2669046608 lock_mode X locks rec but not gap waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0

 0: len 1; hex 01; asc  ;;

 1: len 6; hex 00009f166b2f; asc     k/;;

 2: len 7; hex 360000c0020110; asc 6      ;;

 3: len 5; hex 99b2fa4b0d; asc    K ;;

------------------

---TRANSACTION 2669046585, ACTIVE (PREPARED) 550 sec

2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 2

MariaDB thread id 3470444, OS thread handle 140090649003584, query id 380457783 Waiting for prior transaction to commit

---TRANSACTION 2669046574, ACTIVE (PREPARED) 550 sec

3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2

MariaDB thread id 3470445, OS thread handle 140090648389184, query id 380457773 Waiting for prior transaction to commit

---TRANSACTION (0x7f6aa453f680), not started

0 lock struct(s), heap size 1128, 0 row lock(s)

---TRANSACTION (0x7f6aa453eb80), not started

0 lock struct(s), heap size 1128, 0 row lock(s)

--------

FILE I/O

--------

Pending flushes (fsync): 0

73352 OS file reads, 300770765 OS file writes, 2527252 OS fsyncs

0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

---

LOG

---

Log sequence number 3210682942432

Log flushed up to   3210682942432

Pages flushed up to 3210682942432

Last checkpoint at  3210682942408

----------------------

BUFFER POOL AND MEMORY

----------------------

Total large memory allocated 3808428032

Dictionary memory allocated 23218440

Buffer pool size   228160

Free buffers       129541

Database pages     98619

Old database pages 36423

Modified db pages  0

Percent of dirty pages(LRU & free pages): 0.000

Max dirty pages percent: 40.000

Pending reads 0

Pending writes: LRU 0, flush list 0

Pages made young 170619, not young 32960930

0.00 youngs/s, 0.00 non-youngs/s

Pages read 72866, created 30503592, written 115666167

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: 98619, 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

duplicates

MDEV-21953 deadlock between BACKUP STAGE BLOCK_COMMIT and parallel replication

Closed

MDEV-31840 Parallel replication undetected deadlocks with outside transaction

Open

relates to

MDEV-36137 parallel replication deadlock between DML in one domain and DDL in another

Open

Activity

Ascending order - Click to sort in descending order

VAROQUI Stephane created issue - 2024-03-29 15:42

Brandon Nesterenko made changes - 2024-04-05 16:49

Field	Original Value	New Value
Description	Following Brandon advice to open a ticket after Zulip Issue: Replication sql thread stopped in optimistic but ok in conservative Context: Concurrent writes on 2 tables with same name but different DB Workaround Moving to conservative fixed the replication sql thread regular stop {code} select * from api_check; +----+---------------------+ \| id \| last_check \| +----+---------------------+ \| 1 \| 2024-03-29 09:49:10 \| +----+---------------------+ 1 row in set (0.001 sec) MariaDB [mixr_user]> show create table api_check; +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ \| Table \| Create Table \| +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ \| api_check \| CREATE TABLE api_check ( id tinyint(3) unsigned NOT NULL, last_check datetime NOT NULL DEFAULT '0000-00-00 00:00:00', PRIMARY KEY (id) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci \| +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.000 sec) {code} Processlist: {code} \| 3455587 \| system user \| \| wpmixrgen \| Slave_worker \| 20 \| Update_rows_log_event::find_row(-1) on table api_check \| update api_check set last_check = '2024-03-29 00:34:28' where id = 1 \| 0.000 \| \| 3455588 \| system user \| \| mixr_user \| Slave_worker \| 20 \| Update_rows_log_event::find_row(-1) on table api_check \| update api_check set last_check = '2024-03-29 00:34:27' where id = 1 \| 0.000 \| \| {code} No views in the middle {code} MariaDB [wpmixrgen]> show full tables like 'api_check'; +---------------------------------+------------+ \| Tables_in_wpmixrgen (api_check) \| Table_type \| +---------------------------------+------------+ \| api_check \| BASE TABLE \| +---------------------------------+------------+ 1 row in set (0.002 sec) Database changed MariaDB [mixr_user]> show full tables like 'api_check'; +---------------------------------+------------+ \| Tables_in_mixr_user (api_check) \| Table_type \| +---------------------------------+------------+ \| api_check \| BASE TABLE \| +---------------------------------+------------+ 1 row in set (0.001 sec) {code} Bonus: Stop all slaves could stale when in such deadlock {code} \| 3460647 \| root \| 10.48.0.1:55828 \| NULL \| Killed \| 186 \| Killing slave \| stop all slaves {code} Metadata lock state: {code} +-----------+----------------------+---------------+---------------------+--------------+----------------+ \| THREAD_ID \| LOCK_MODE \| LOCK_DURATION \| LOCK_TYPE \| TABLE_SCHEMA \| TABLE_NAME \| +-----------+----------------------+---------------+---------------------+--------------+----------------+ \| 3470443 \| MDL_BACKUP_TRANS_DML \| NULL \| Backup lock \| \| \| \| 3470438 \| MDL_BACKUP_TRANS_DML \| NULL \| Backup lock \| \| \| \| 3470445 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mixr_user \| api_check \| \| 3470438 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mixr_user \| api_check \| \| 3470442 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| api_check \| \| 3470443 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| api_check \| \| 3470442 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470445 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470444 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470444 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| schedule_log \| +-----------+----------------------+---------------+---------------------+--------------+----------------+ 10 rows in set (0.001 sec) {code} INNODB_TRX: {code} trx_id: 2669046603 trx_state: LOCK WAIT trx_started: 2024-03-29 15:48:18 trx_requested_lock_id: 2669046603:27938:3:2 trx_wait_started: 2024-03-29 15:48:18 trx_weight: 2 trx_mysql_thread_id: 3470443 trx_query: update api_check set last_check = '2024-03-29 04:44:09' where id = 1 trx_operation_state: starting index read trx_tables_in_use: 1 trx_tables_locked: 1 trx_lock_structs: 2 trx_lock_memory_bytes: 1128 trx_rows_locked: 1 trx_rows_modified: 0 trx_concurrency_tickets: 0 trx_isolation_level: REPEATABLE READ trx_unique_checks: 1 trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_is_read_only: 0 trx_autocommit_non_locking: 0 --- trx_id: 2669046602 trx_state: LOCK WAIT trx_started: 2024-03-29 15:48:18 trx_requested_lock_id: 2669046602:27887:3:2 trx_wait_started: 2024-03-29 15:48:18 trx_weight: 2 trx_mysql_thread_id: 3470438 trx_query: update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1 trx_operation_state: starting index read trx_tables_in_use: 1 trx_tables_locked: 1 trx_lock_structs: 2 trx_lock_memory_bytes: 1128 trx_rows_locked: 1 trx_rows_modified: 0 trx_concurrency_tickets: 0 trx_isolation_level: REPEATABLE READ trx_unique_checks: 1 trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_is_read_only: 0 trx_autocommit_non_locking: 0 {code} InnoDB Status: {code} MariaDB [information_schema]> show engine innodb status\G ************************* 1. row ************************* Type: InnoDB Name: Status: ===================================== 2024-03-29 15:51:38 0x7f696c107640 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 1 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 3704919 srv_idle srv_master_thread log flush and writes: 3704803 ---------- SEMAPHORES ---------- ------------ TRANSACTIONS ------------ Trx id counter 2669046610 Purge done for trx's n:o < 2669046590 undo n:o < 0 state: running History list length 2 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 2669046609, ACTIVE 50 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s) MariaDB thread id 3470438, OS thread handle 140090653918784, query id 380459332 Update_rows_log_event::find_row(-1) on table `api_check` update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1 ------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 27887 page no 3 n bits 8 index PRIMARY of table `mixr_user`.`api_check` trx id 2669046609 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 1; hex 01; asc ;; 1: len 6; hex 00009f166b2e; asc k.;; 2: len 7; hex 350000c0030110; asc 5 ;; 3: len 5; hex 99b2fa4b0e; asc K ;; ------------------ ---TRANSACTION (0x7f6aa4544380), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa4543880), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa4542d80), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION 2669046575, ACTIVE (PREPARED) 550 sec 3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2 MariaDB thread id 3470442, OS thread handle 140090649925184, query id 380457775 Waiting for prior transaction to commit ---TRANSACTION 2669046608, ACTIVE 50 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s) MariaDB thread id 3470443, OS thread handle 140090649310784, query id 380459331 Update_rows_log_event::find_row(-1) on table `api_check` update `api_check` set `last_check` = '2024-03-29 04:44:09' where `id` = 1 ------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 27938 page no 3 n bits 8 index PRIMARY of table `wpmixrgen`.`api_check` trx id 2669046608 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 1; hex 01; asc ;; 1: len 6; hex 00009f166b2f; asc k/;; 2: len 7; hex 360000c0020110; asc 6 ;; 3: len 5; hex 99b2fa4b0d; asc K ;; ------------------ ---TRANSACTION 2669046585, ACTIVE (PREPARED) 550 sec 2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 2 MariaDB thread id 3470444, OS thread handle 140090649003584, query id 380457783 Waiting for prior transaction to commit ---TRANSACTION 2669046574, ACTIVE (PREPARED) 550 sec 3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2 MariaDB thread id 3470445, OS thread handle 140090648389184, query id 380457773 Waiting for prior transaction to commit ---TRANSACTION (0x7f6aa453f680), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa453eb80), not started 0 lock struct(s), heap size 1128, 0 row lock(s) -------- FILE I/O -------- Pending flushes (fsync): 0 73352 OS file reads, 300770765 OS file writes, 2527252 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s --- LOG --- Log sequence number 3210682942432 Log flushed up to 3210682942432 Pages flushed up to 3210682942432 Last checkpoint at 3210682942408 ---------------------- BUFFER POOL AND MEMORY ---------------------- Total large memory allocated 3808428032 Dictionary memory allocated 23218440 Buffer pool size 228160 Free buffers 129541 Database pages 98619 Old database pages 36423 Modified db pages 0 Percent of dirty pages(LRU & free pages): 0.000 Max dirty pages percent: 40.000 Pending reads 0 Pending writes: LRU 0, flush list 0 Pages made young 170619, not young 32960930 0.00 youngs/s, 0.00 non-youngs/s Pages read 72866, created 30503592, written 115666167 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: 98619, 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) {code}	Following Brandon advice to open a ticket after Zulip (the initial conversation was done via DM, but an official Zulip topic has been created for this since: [link\|https://mariadb.zulipchat.com/#narrow/stream/118759-general/topic/MDEV-33798.3A.20Row.20based.20optimistic.20deadlock]) Issue: Replication sql thread stopped in optimistic but ok in conservative Context: Concurrent writes on 2 tables with same name but different DB Workaround Moving to conservative fixed the replication sql thread regular stop {code} select * from api_check; +----+---------------------+ \| id \| last_check \| +----+---------------------+ \| 1 \| 2024-03-29 09:49:10 \| +----+---------------------+ 1 row in set (0.001 sec) MariaDB [mixr_user]> show create table api_check; +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ \| Table \| Create Table \| +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ \| api_check \| CREATE TABLE api_check ( id tinyint(3) unsigned NOT NULL, last_check datetime NOT NULL DEFAULT '0000-00-00 00:00:00', PRIMARY KEY (id) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci \| +-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.000 sec) {code} Processlist: {code} \| 3455587 \| system user \| \| wpmixrgen \| Slave_worker \| 20 \| Update_rows_log_event::find_row(-1) on table api_check \| update api_check set last_check = '2024-03-29 00:34:28' where id = 1 \| 0.000 \| \| 3455588 \| system user \| \| mixr_user \| Slave_worker \| 20 \| Update_rows_log_event::find_row(-1) on table api_check \| update api_check set last_check = '2024-03-29 00:34:27' where id = 1 \| 0.000 \| \| {code} No views in the middle {code} MariaDB [wpmixrgen]> show full tables like 'api_check'; +---------------------------------+------------+ \| Tables_in_wpmixrgen (api_check) \| Table_type \| +---------------------------------+------------+ \| api_check \| BASE TABLE \| +---------------------------------+------------+ 1 row in set (0.002 sec) Database changed MariaDB [mixr_user]> show full tables like 'api_check'; +---------------------------------+------------+ \| Tables_in_mixr_user (api_check) \| Table_type \| +---------------------------------+------------+ \| api_check \| BASE TABLE \| +---------------------------------+------------+ 1 row in set (0.001 sec) {code} Bonus: Stop all slaves could stale when in such deadlock {code} \| 3460647 \| root \| 10.48.0.1:55828 \| NULL \| Killed \| 186 \| Killing slave \| stop all slaves {code} Metadata lock state: {code} +-----------+----------------------+---------------+---------------------+--------------+----------------+ \| THREAD_ID \| LOCK_MODE \| LOCK_DURATION \| LOCK_TYPE \| TABLE_SCHEMA \| TABLE_NAME \| +-----------+----------------------+---------------+---------------------+--------------+----------------+ \| 3470443 \| MDL_BACKUP_TRANS_DML \| NULL \| Backup lock \| \| \| \| 3470438 \| MDL_BACKUP_TRANS_DML \| NULL \| Backup lock \| \| \| \| 3470445 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mixr_user \| api_check \| \| 3470438 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mixr_user \| api_check \| \| 3470442 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| api_check \| \| 3470443 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| api_check \| \| 3470442 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470445 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470444 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| mysql \| gtid_slave_pos \| \| 3470444 \| MDL_SHARED_WRITE \| NULL \| Table metadata lock \| wpmixrgen \| schedule_log \| +-----------+----------------------+---------------+---------------------+--------------+----------------+ 10 rows in set (0.001 sec) {code} INNODB_TRX: {code} trx_id: 2669046603 trx_state: LOCK WAIT trx_started: 2024-03-29 15:48:18 trx_requested_lock_id: 2669046603:27938:3:2 trx_wait_started: 2024-03-29 15:48:18 trx_weight: 2 trx_mysql_thread_id: 3470443 trx_query: update api_check set last_check = '2024-03-29 04:44:09' where id = 1 trx_operation_state: starting index read trx_tables_in_use: 1 trx_tables_locked: 1 trx_lock_structs: 2 trx_lock_memory_bytes: 1128 trx_rows_locked: 1 trx_rows_modified: 0 trx_concurrency_tickets: 0 trx_isolation_level: REPEATABLE READ trx_unique_checks: 1 trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_is_read_only: 0 trx_autocommit_non_locking: 0 --- trx_id: 2669046602 trx_state: LOCK WAIT trx_started: 2024-03-29 15:48:18 trx_requested_lock_id: 2669046602:27887:3:2 trx_wait_started: 2024-03-29 15:48:18 trx_weight: 2 trx_mysql_thread_id: 3470438 trx_query: update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1 trx_operation_state: starting index read trx_tables_in_use: 1 trx_tables_locked: 1 trx_lock_structs: 2 trx_lock_memory_bytes: 1128 trx_rows_locked: 1 trx_rows_modified: 0 trx_concurrency_tickets: 0 trx_isolation_level: REPEATABLE READ trx_unique_checks: 1 trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_is_read_only: 0 trx_autocommit_non_locking: 0 {code} InnoDB Status: {code} MariaDB [information_schema]> show engine innodb status\G ************************* 1. row ************************* Type: InnoDB Name: Status: ===================================== 2024-03-29 15:51:38 0x7f696c107640 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 1 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 3704919 srv_idle srv_master_thread log flush and writes: 3704803 ---------- SEMAPHORES ---------- ------------ TRANSACTIONS ------------ Trx id counter 2669046610 Purge done for trx's n:o < 2669046590 undo n:o < 0 state: running History list length 2 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 2669046609, ACTIVE 50 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s) MariaDB thread id 3470438, OS thread handle 140090653918784, query id 380459332 Update_rows_log_event::find_row(-1) on table `api_check` update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1 ------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 27887 page no 3 n bits 8 index PRIMARY of table `mixr_user`.`api_check` trx id 2669046609 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 1; hex 01; asc ;; 1: len 6; hex 00009f166b2e; asc k.;; 2: len 7; hex 350000c0030110; asc 5 ;; 3: len 5; hex 99b2fa4b0e; asc K ;; ------------------ ---TRANSACTION (0x7f6aa4544380), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa4543880), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa4542d80), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION 2669046575, ACTIVE (PREPARED) 550 sec 3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2 MariaDB thread id 3470442, OS thread handle 140090649925184, query id 380457775 Waiting for prior transaction to commit ---TRANSACTION 2669046608, ACTIVE 50 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s) MariaDB thread id 3470443, OS thread handle 140090649310784, query id 380459331 Update_rows_log_event::find_row(-1) on table `api_check` update `api_check` set `last_check` = '2024-03-29 04:44:09' where `id` = 1 ------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 27938 page no 3 n bits 8 index PRIMARY of table `wpmixrgen`.`api_check` trx id 2669046608 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 1; hex 01; asc ;; 1: len 6; hex 00009f166b2f; asc k/;; 2: len 7; hex 360000c0020110; asc 6 ;; 3: len 5; hex 99b2fa4b0d; asc K ;; ------------------ ---TRANSACTION 2669046585, ACTIVE (PREPARED) 550 sec 2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 2 MariaDB thread id 3470444, OS thread handle 140090649003584, query id 380457783 Waiting for prior transaction to commit ---TRANSACTION 2669046574, ACTIVE (PREPARED) 550 sec 3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2 MariaDB thread id 3470445, OS thread handle 140090648389184, query id 380457773 Waiting for prior transaction to commit ---TRANSACTION (0x7f6aa453f680), not started 0 lock struct(s), heap size 1128, 0 row lock(s) ---TRANSACTION (0x7f6aa453eb80), not started 0 lock struct(s), heap size 1128, 0 row lock(s) -------- FILE I/O -------- Pending flushes (fsync): 0 73352 OS file reads, 300770765 OS file writes, 2527252 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s --- LOG --- Log sequence number 3210682942432 Log flushed up to 3210682942432 Pages flushed up to 3210682942432 Last checkpoint at 3210682942408 ---------------------- BUFFER POOL AND MEMORY ---------------------- Total large memory allocated 3808428032 Dictionary memory allocated 23218440 Buffer pool size 228160 Free buffers 129541 Database pages 98619 Old database pages 36423 Modified db pages 0 Percent of dirty pages(LRU & free pages): 0.000 Max dirty pages percent: 40.000 Pending reads 0 Pending writes: LRU 0, flush list 0 Pages made young 170619, not young 32960930 0.00 youngs/s, 0.00 non-youngs/s Pages read 72866, created 30503592, written 115666167 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: 98619, 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) {code}

Brandon Nesterenko made changes - 2024-04-05 16:50

Description

Following Brandon advice to open a ticket after Zulip (the initial conversation was done via DM, but an official Zulip topic has been created for this since: [link|https://mariadb.zulipchat.com/#narrow/stream/118759-general/topic/MDEV-33798.3A.20Row.20based.20optimistic.20deadlock])

Issue:
Replication sql thread stopped in optimistic but ok in conservative

Context:
Concurrent writes on 2 tables with same name but different DB

Workaround
Moving to conservative fixed the replication sql thread regular stop

{code}
select * from api_check;
+----+---------------------+
| id | last_check |
+----+---------------------+
| 1 | 2024-03-29 09:49:10 |
+----+---------------------+
1 row in set (0.001 sec)

MariaDB [mixr_user]> show create table api_check;
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| api_check | CREATE TABLE api_check (
id tinyint(3) unsigned NOT NULL,
last_check datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci |
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.000 sec)
{code}

Processlist:

{code}
| 3455587 | system user | | wpmixrgen | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:28' where id = 1 | 0.000 |
| 3455588 | system user | | mixr_user | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:27' where id = 1 | 0.000 |
|
{code}

No views in the middle
{code}
MariaDB [wpmixrgen]> show full tables like 'api_check';
+---------------------------------+------------+
| Tables_in_wpmixrgen (api_check) | Table_type |
+---------------------------------+------------+
| api_check | BASE TABLE |
+---------------------------------+------------+
1 row in set (0.002 sec)
Database changed
MariaDB [mixr_user]> show full tables like 'api_check';
+---------------------------------+------------+
| Tables_in_mixr_user (api_check) | Table_type |
+---------------------------------+------------+
| api_check | BASE TABLE |
+---------------------------------+------------+
1 row in set (0.001 sec)
{code}

Bonus:
Stop all slaves could stale when in such deadlock
{code}
| 3460647 | root | 10.48.0.1:55828 | NULL | Killed | 186 | Killing slave | stop all slaves
{code}

Metadata lock state:
{code}
+-----------+----------------------+---------------+---------------------+--------------+----------------+
| THREAD_ID | LOCK_MODE | LOCK_DURATION | LOCK_TYPE | TABLE_SCHEMA | TABLE_NAME |
+-----------+----------------------+---------------+---------------------+--------------+----------------+
| 3470443 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |
| 3470438 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |
| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |
| 3470438 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |
| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |
| 3470443 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |
| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | schedule_log |
+-----------+----------------------+---------------+---------------------+--------------+----------------+
10 rows in set (0.001 sec)
{code}

INNODB_TRX:

{code}
trx_id: 2669046603
trx_state: LOCK WAIT
trx_started: 2024-03-29 15:48:18
trx_requested_lock_id: 2669046603:27938:3:2
trx_wait_started: 2024-03-29 15:48:18
trx_weight: 2
trx_mysql_thread_id: 3470443
trx_query: update api_check set last_check = '2024-03-29 04:44:09' where id = 1
trx_operation_state: starting index read
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 1128
trx_rows_locked: 1
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_is_read_only: 0
trx_autocommit_non_locking: 0
---
trx_id: 2669046602
                 trx_state: LOCK WAIT
               trx_started: 2024-03-29 15:48:18
     trx_requested_lock_id: 2669046602:27887:3:2
          trx_wait_started: 2024-03-29 15:48:18
                trx_weight: 2
       trx_mysql_thread_id: 3470438
                 trx_query: update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1
       trx_operation_state: starting index read
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
          trx_is_read_only: 0
trx_autocommit_non_locking: 0

{code}

InnoDB Status:

{code}
MariaDB [information_schema]> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-03-29 15:51:38 0x7f696c107640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 1 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 3704919 srv_idle
srv_master_thread log flush and writes: 3704803
----------
SEMAPHORES
----------
------------
TRANSACTIONS
------------
Trx id counter 2669046610
Purge done for trx's n:o < 2669046590 undo n:o < 0 state: running
History list length 2
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 2669046609, ACTIVE 50 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MariaDB thread id 3470438, OS thread handle 140090653918784, query id 380459332 Update_rows_log_event::find_row(-1) on table `api_check`
update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1
------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 27887 page no 3 n bits 8 index PRIMARY of table `mixr_user`.`api_check` trx id 2669046609 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 1; hex 01; asc ;;
1: len 6; hex 00009f166b2e; asc k.;;
2: len 7; hex 350000c0030110; asc 5 ;;
3: len 5; hex 99b2fa4b0e; asc K ;;

------------------
---TRANSACTION (0x7f6aa4544380), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa4543880), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa4542d80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 2669046575, ACTIVE (PREPARED) 550 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MariaDB thread id 3470442, OS thread handle 140090649925184, query id 380457775 Waiting for prior transaction to commit
---TRANSACTION 2669046608, ACTIVE 50 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MariaDB thread id 3470443, OS thread handle 140090649310784, query id 380459331 Update_rows_log_event::find_row(-1) on table `api_check`
update `api_check` set `last_check` = '2024-03-29 04:44:09' where `id` = 1
------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 27938 page no 3 n bits 8 index PRIMARY of table `wpmixrgen`.`api_check` trx id 2669046608 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 1; hex 01; asc ;;
1: len 6; hex 00009f166b2f; asc k/;;
2: len 7; hex 360000c0020110; asc 6 ;;
3: len 5; hex 99b2fa4b0d; asc K ;;

------------------
---TRANSACTION 2669046585, ACTIVE (PREPARED) 550 sec
2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 2
MariaDB thread id 3470444, OS thread handle 140090649003584, query id 380457783 Waiting for prior transaction to commit
---TRANSACTION 2669046574, ACTIVE (PREPARED) 550 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MariaDB thread id 3470445, OS thread handle 140090648389184, query id 380457773 Waiting for prior transaction to commit
---TRANSACTION (0x7f6aa453f680), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa453eb80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
Pending flushes (fsync): 0
73352 OS file reads, 300770765 OS file writes, 2527252 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
---
LOG
---
Log sequence number 3210682942432
Log flushed up to 3210682942432
Pages flushed up to 3210682942432
Last checkpoint at 3210682942408
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 3808428032
Dictionary memory allocated 23218440
Buffer pool size 228160
Free buffers 129541
Database pages 98619
Old database pages 36423
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 40.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 170619, not young 32960930
0.00 youngs/s, 0.00 non-youngs/s
Pages read 72866, created 30503592, written 115666167
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: 98619, 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)
{code}

Following Brandon advice to open a ticket after Zulip (the initial conversation was done via DM, but an official Zulip topic has been created for this since with more details (e.g. variables, show slave status, etc): [link|https://mariadb.zulipchat.com/#narrow/stream/118759-general/topic/MDEV-33798.3A.20Row.20based.20optimistic.20deadlock])

Issue:
Replication sql thread stopped in optimistic but ok in conservative

Context:
Concurrent writes on 2 tables with same name but different DB

Workaround
Moving to conservative fixed the replication sql thread regular stop

{code}
select * from api_check;
+----+---------------------+
| id | last_check |
+----+---------------------+
| 1 | 2024-03-29 09:49:10 |
+----+---------------------+
1 row in set (0.001 sec)

MariaDB [mixr_user]> show create table api_check;
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| api_check | CREATE TABLE api_check (
id tinyint(3) unsigned NOT NULL,
last_check datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci |
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.000 sec)
{code}

Processlist:

{code}
| 3455587 | system user | | wpmixrgen | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:28' where id = 1 | 0.000 |
| 3455588 | system user | | mixr_user | Slave_worker | 20 | Update_rows_log_event::find_row(-1) on table api_check | update api_check set last_check = '2024-03-29 00:34:27' where id = 1 | 0.000 |
|
{code}

No views in the middle
{code}
MariaDB [wpmixrgen]> show full tables like 'api_check';
+---------------------------------+------------+
| Tables_in_wpmixrgen (api_check) | Table_type |
+---------------------------------+------------+
| api_check | BASE TABLE |
+---------------------------------+------------+
1 row in set (0.002 sec)
Database changed
MariaDB [mixr_user]> show full tables like 'api_check';
+---------------------------------+------------+
| Tables_in_mixr_user (api_check) | Table_type |
+---------------------------------+------------+
| api_check | BASE TABLE |
+---------------------------------+------------+
1 row in set (0.001 sec)
{code}

Bonus:
Stop all slaves could stale when in such deadlock
{code}
| 3460647 | root | 10.48.0.1:55828 | NULL | Killed | 186 | Killing slave | stop all slaves
{code}

Metadata lock state:
{code}
+-----------+----------------------+---------------+---------------------+--------------+----------------+
| THREAD_ID | LOCK_MODE | LOCK_DURATION | LOCK_TYPE | TABLE_SCHEMA | TABLE_NAME |
+-----------+----------------------+---------------+---------------------+--------------+----------------+
| 3470443 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |
| 3470438 | MDL_BACKUP_TRANS_DML | NULL | Backup lock | | |
| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |
| 3470438 | MDL_SHARED_WRITE | NULL | Table metadata lock | mixr_user | api_check |
| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |
| 3470443 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | api_check |
| 3470442 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470445 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | mysql | gtid_slave_pos |
| 3470444 | MDL_SHARED_WRITE | NULL | Table metadata lock | wpmixrgen | schedule_log |
+-----------+----------------------+---------------+---------------------+--------------+----------------+
10 rows in set (0.001 sec)
{code}

INNODB_TRX:

{code}
trx_id: 2669046603
trx_state: LOCK WAIT
trx_started: 2024-03-29 15:48:18
trx_requested_lock_id: 2669046603:27938:3:2
trx_wait_started: 2024-03-29 15:48:18
trx_weight: 2
trx_mysql_thread_id: 3470443
trx_query: update api_check set last_check = '2024-03-29 04:44:09' where id = 1
trx_operation_state: starting index read
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 1128
trx_rows_locked: 1
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_is_read_only: 0
trx_autocommit_non_locking: 0
---
trx_id: 2669046602
                 trx_state: LOCK WAIT
               trx_started: 2024-03-29 15:48:18
     trx_requested_lock_id: 2669046602:27887:3:2
          trx_wait_started: 2024-03-29 15:48:18
                trx_weight: 2
       trx_mysql_thread_id: 3470438
                 trx_query: update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1
       trx_operation_state: starting index read
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
          trx_is_read_only: 0
trx_autocommit_non_locking: 0

{code}

InnoDB Status:

{code}
MariaDB [information_schema]> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-03-29 15:51:38 0x7f696c107640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 1 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 3704919 srv_idle
srv_master_thread log flush and writes: 3704803
----------
SEMAPHORES
----------
------------
TRANSACTIONS
------------
Trx id counter 2669046610
Purge done for trx's n:o < 2669046590 undo n:o < 0 state: running
History list length 2
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 2669046609, ACTIVE 50 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MariaDB thread id 3470438, OS thread handle 140090653918784, query id 380459332 Update_rows_log_event::find_row(-1) on table `api_check`
update `api_check` set `last_check` = '2024-03-29 04:44:13' where `id` = 1
------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 27887 page no 3 n bits 8 index PRIMARY of table `mixr_user`.`api_check` trx id 2669046609 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 1; hex 01; asc ;;
1: len 6; hex 00009f166b2e; asc k.;;
2: len 7; hex 350000c0030110; asc 5 ;;
3: len 5; hex 99b2fa4b0e; asc K ;;

------------------
---TRANSACTION (0x7f6aa4544380), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa4543880), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa4542d80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 2669046575, ACTIVE (PREPARED) 550 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MariaDB thread id 3470442, OS thread handle 140090649925184, query id 380457775 Waiting for prior transaction to commit
---TRANSACTION 2669046608, ACTIVE 50 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MariaDB thread id 3470443, OS thread handle 140090649310784, query id 380459331 Update_rows_log_event::find_row(-1) on table `api_check`
update `api_check` set `last_check` = '2024-03-29 04:44:09' where `id` = 1
------- TRX HAS BEEN WAITING 49554452 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 27938 page no 3 n bits 8 index PRIMARY of table `wpmixrgen`.`api_check` trx id 2669046608 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 1; hex 01; asc ;;
1: len 6; hex 00009f166b2f; asc k/;;
2: len 7; hex 360000c0020110; asc 6 ;;
3: len 5; hex 99b2fa4b0d; asc K ;;

------------------
---TRANSACTION 2669046585, ACTIVE (PREPARED) 550 sec
2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 2
MariaDB thread id 3470444, OS thread handle 140090649003584, query id 380457783 Waiting for prior transaction to commit
---TRANSACTION 2669046574, ACTIVE (PREPARED) 550 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MariaDB thread id 3470445, OS thread handle 140090648389184, query id 380457773 Waiting for prior transaction to commit
---TRANSACTION (0x7f6aa453f680), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7f6aa453eb80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
Pending flushes (fsync): 0
73352 OS file reads, 300770765 OS file writes, 2527252 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
---
LOG
---
Log sequence number 3210682942432
Log flushed up to 3210682942432
Pages flushed up to 3210682942432
Last checkpoint at 3210682942408
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 3808428032
Dictionary memory allocated 23218440
Buffer pool size 228160
Free buffers 129541
Database pages 98619
Old database pages 36423
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 40.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 170619, not young 32960930
0.00 youngs/s, 0.00 non-youngs/s
Pages read 72866, created 30503592, written 115666167
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: 98619, 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)
{code}

VAROQUI Stephane made changes - 2024-04-09 19:58

Link

This issue duplicates ~~MDEV-21953~~ [ ~~MDEV-21953~~ ]

VAROQUI Stephane added a comment - 2024-04-09 19:59

The master is 10.3.32-MariaDB and possibly affected by ~~MDEV-21953~~

VAROQUI Stephane added a comment - 2024-04-09 19:59 The master is 10.3.32-MariaDB and possibly affected by MDEV-21953

VAROQUI Stephane added a comment - 2024-04-29 09:42

After upgrading the master to 10.11.7 we still observe the deadlock

VAROQUI Stephane added a comment - 2024-04-29 09:42 After upgrading the master to 10.11.7 we still observe the deadlock

VAROQUI Stephane made changes - 2024-04-30 12:38

Link

This issue duplicates MDEV-31840 [ MDEV-31840 ]

VAROQUI Stephane made changes - 2024-04-30 12:41

Summary

ROW base optimistic deadlock with concurrent writes on same table name different db

ROW base optimistic deadlock with concurrent writes on same table row and multi domain

Kristian Nielsen made changes - 2024-04-30 12:59

Assignee

Kristian Nielsen [ knielsen ]

Kristian Nielsen made changes - 2024-04-30 12:59

Fix Version/s

10.6 [ 24028 ]

Kristian Nielsen added a comment - 2024-04-30 13:13

Thanks to Stephane's helpful assistance with reproducing this on a test server, I found the root cause for this.

The problem occurs when there is a conflict between transactions that are replicated in different domain_id and/or different master connections. The deadlock kill mechanism is currently disabled when either of these differ.

In the test environment, this caused a hang because T1 and T2 both modified the same table, but had different domain id. T1 would do a row lock wait on T2, and T2 a wait_for_prior_commit on T1 (GTID was disabled on the test server).

I believe the production issue may be slightly different due to using GTID, but can hang with transactions T1,T2 in one domain/master connection and transactions U1, U2 in another:

T1 row low wait on U2
U2 wait_for_prior_commit on U1
U1 row lock wait on T2
T2 wait_for_prior_commit on T1

My idea for a fix is that we can extend to deadlock kill T2 and U2 in these cases. In general, we will deadlock kill a transaction if it blocks a transaction in a different domain/master connection, if that transaction is being speculatively replicated (SPECULATE_OPTIMISTIC).

This should prevent these kinds of hangs, because a blocking transaction will now be deadlock killed whenever a cycle occurs where wait_for_prior_commit is called while holding row locks.

In the above example, killing both T2 and U2 is overly conservative (just one of them would be sufficient). But conflicts between different domains are expected to be rare (as they are technically not supported / are not replicated in deterministic order), so this I think is not an issue.

I have pushed an initial patch along these ideas to branch bb-10.11-~~MDEV-33798~~-knielsen-pkgtest

Kristian Nielsen added a comment - 2024-04-30 13:13 Thanks to Stephane's helpful assistance with reproducing this on a test server, I found the root cause for this. The problem occurs when there is a conflict between transactions that are replicated in different domain_id and/or different master connections. The deadlock kill mechanism is currently disabled when either of these differ. In the test environment, this caused a hang because T1 and T2 both modified the same table, but had different domain id. T1 would do a row lock wait on T2, and T2 a wait_for_prior_commit on T1 (GTID was disabled on the test server). I believe the production issue may be slightly different due to using GTID, but can hang with transactions T1,T2 in one domain/master connection and transactions U1, U2 in another: T1 row low wait on U2 U2 wait_for_prior_commit on U1 U1 row lock wait on T2 T2 wait_for_prior_commit on T1 My idea for a fix is that we can extend to deadlock kill T2 and U2 in these cases. In general, we will deadlock kill a transaction if it blocks a transaction in a different domain/master connection, if that transaction is being speculatively replicated (SPECULATE_OPTIMISTIC). This should prevent these kinds of hangs, because a blocking transaction will now be deadlock killed whenever a cycle occurs where wait_for_prior_commit is called while holding row locks. In the above example, killing both T2 and U2 is overly conservative (just one of them would be sufficient). But conflicts between different domains are expected to be rare (as they are technically not supported / are not replicated in deterministic order), so this I think is not an issue. I have pushed an initial patch along these ideas to branch bb-10.11- MDEV-33798 -knielsen-pkgtest

Daniel Black added a comment - 2024-05-01 01:53

Packages containing this fix can be obtained using the the .repo / .list files under the appropriate platform under the URL https://ci.mariadb.org/46168/

A container containing this fix can be obtained as: quay.io/mariadb-foundation/mariadb-devel:10.11-mdev-33798-knielsen-pkgtest

Feedback for knielsen would be much appreciated.

Daniel Black added a comment - 2024-05-01 01:53 Packages containing this fix can be obtained using the the .repo / .list files under the appropriate platform under the URL https://ci.mariadb.org/46168/ A container containing this fix can be obtained as: quay.io/mariadb-foundation/mariadb-devel:10.11-mdev-33798-knielsen-pkgtest Feedback for knielsen would be much appreciated.

VAROQUI Stephane added a comment - 2024-05-01 14:04

@Daniel Black in production looks good so far let's wait 1 week or 2, so great to have quay

VAROQUI Stephane added a comment - 2024-05-01 14:04 @Daniel Black in production looks good so far let's wait 1 week or 2, so great to have quay

Kristian Nielsen made changes - 2024-05-02 18:59

Status

Open [ 1 ]

In Progress [ 3 ]

Kristian Nielsen made changes - 2024-05-02 20:29

Fix Version/s		10.6.18 [ 29627 ]
Fix Version/s	10.6 [ 24028 ]

Kristian Nielsen added a comment - 2024-05-02 20:30

I've pushed a fix for this to 10.6, but we can keep it open while we wait and see if the patch runs stable in Stephane's environment.

Kristian Nielsen added a comment - 2024-05-02 20:30 I've pushed a fix for this to 10.6, but we can keep it open while we wait and see if the patch runs stable in Stephane's environment.

Sergei Golubchik made changes - 2024-05-06 15:25

Fix Version/s		10.6 [ 24028 ]
Fix Version/s		10.11 [ 27614 ]
Fix Version/s	10.6.18 [ 29627 ]

Kristian Nielsen made changes - 2024-06-12 09:42

Fix Version/s		10.6.18 [ 29627 ]
Fix Version/s	10.6 [ 24028 ]
Fix Version/s	10.11 [ 27614 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

JiraAutomate made changes - 2024-06-12 09:42

Fix Version/s		10.11.8 [ 29630 ]
Fix Version/s		11.0.6 [ 29628 ]
Fix Version/s		11.1.5 [ 29629 ]
Fix Version/s		11.2.4 [ 29631 ]
Fix Version/s		11.4.2 [ 29633 ]

Kristian Nielsen made changes - 2025-02-21 09:54

Link

This issue relates to MDEV-36137 [ MDEV-36137 ]

People

Assignee:: Kristian Nielsen

Reporter:: VAROQUI Stephane

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 2024-03-29 15:42

Updated:: 2025-02-21 09:54

Resolved:: 2024-06-12 09:42

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration