Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-37977

InnoDB deadlock report incorrectly reports rolledback transaction number

    XMLWordPrintable

Details

    Description

      In MDEV-37974 it's clear that InnoDB deadlock report incorrectly states the rolled back transaction.

      Specifically for the following audit log:

      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,5,QUERY,,'SET GLOBAL server_audit_logging=\'ON\'',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,6,QUERY,,'CREATE DATABASE test',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,7,QUERY,,'SELECT DATABASE()',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,9,QUERY,test,'show databases',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,10,QUERY,test,'show tables',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,11,QUERY,test,'CREATE TABLE parent (id bigint(20) NOT NULL AUTO_INCREMENT PRIMARY KEY) ENGINE InnoDB',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,12,QUERY,test,'CREATE TABLE child (id bigint(20) NOT NULL AUTO_INCREMENT PRIMARY KEY,\n                    parent_id bigint(20) NOT NULL,\n                    CONSTRAINT `fk_parent`\n                        FOREIGN KEY (parent_id) REFERENCES parent (id)\n                        ON DELETE CASCADE\n                        ON UPDATE RESTRICT\n                    ) ENGINE InnoDB',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,13,QUERY,test,'INSERT INTO parent (id) VALUES(1), (2), (3)',0
      20251027 18:57:53,f6a52a894ee3,root,172.20.0.1,4,14,QUERY,test,'INSERT INTO child (parent_id) VALUES(1), (2), (3)',0
      20251027 18:58:09,f6a52a894ee3,root,172.20.0.1,3,2,QUERY,,'SELECT DATABASE()',0
      20251027 18:58:09,f6a52a894ee3,root,172.20.0.1,3,17,QUERY,test,'show databases',0
      20251027 18:58:09,f6a52a894ee3,root,172.20.0.1,3,18,QUERY,test,'show tables',0
      20251027 18:58:09,f6a52a894ee3,root,172.20.0.1,3,21,QUERY,test,'START TRANSACTION',0
      20251027 18:58:11,f6a52a894ee3,root,172.20.0.1,3,22,QUERY,test,'DELETE FROM child WHERE parent_id IN (1, 2, 3)',0
      20251027 18:58:20,f6a52a894ee3,root,172.20.0.1,4,23,QUERY,test,'SELECT DATABASE()',0
      20251027 18:58:20,f6a52a894ee3,root,172.20.0.1,4,25,QUERY,test,'START TRANSACTION',0
      20251027 18:58:30,f6a52a894ee3,root,172.20.0.1,3,27,QUERY,test,'INSERT INTO child (parent_id) VALUES (1)',0
      20251027 18:58:30,f6a52a894ee3,root,172.20.0.1,4,26,QUERY,test,'DELETE FROM child WHERE parent_id IN (2, 3)',1213
      20251027 18:58:58,f6a52a894ee3,root,172.20.0.1,4,28,QUERY,test,'SHOW ENGINE INNODB STATUS',0
      20251027 19:00:51,f6a52a894ee3,root,172.20.0.1,3,0,DISCONNECT,test,,0
      20251027 19:00:54,f6a52a894ee3,root,172.20.0.1,4,0,DISCONNECT,test,,0
      

      it is clear that Connection #4, Query #26 encounters the deadlock (result 1213) and is rolled back.

      However the same InnoDB status (Connection #4, Query #28)

      *************************** 1. row ***************************
        Type: InnoDB
        Name: 
      Status: 
      =====================================
      2025-10-27 18:58:58 0x7f0b6c0c1640 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 53 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 113 srv_idle
      srv_master_thread log flush and writes: 113
      ----------
      SEMAPHORES
      ----------
      ------------------------
      LATEST DETECTED DEADLOCK
      ------------------------
      2025-10-27 18:58:30 0x7f0b6c10c640
      *** (1) TRANSACTION:
      TRANSACTION 31, ACTIVE 19 sec inserting
      mysql tables in use 1, locked 1
      LOCK WAIT 7 lock struct(s), heap size 1128, 8 row lock(s), undo log entries 4
      MariaDB thread id 3, OS thread handle 139687034406464, query id 27 172.20.0.1 root Update
      INSERT INTO child (parent_id) VALUES (1)
      *** WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 6 page no 4 n bits 320 index fk_parent of table `test`.`child` trx id 31 lock_mode X locks gap before rec insert intention waiting
      Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000002; asc         ;;
       1: len 8; hex 8000000000000002; asc         ;;
       
      *** CONFLICTING WITH:
      RECORD LOCKS space id 6 page no 4 n bits 320 index fk_parent of table `test`.`child` trx id 31 lock_mode X locks rec but not gap
      Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000002; asc         ;;
       1: len 8; hex 8000000000000002; asc         ;;
       
       
      *** (2) TRANSACTION:
      TRANSACTION 34, ACTIVE 10 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 4, OS thread handle 139687034099264, query id 26 172.20.0.1 root Updating
      DELETE FROM child WHERE parent_id IN (2, 3)
      *** WAITING FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 6 page no 4 n bits 320 index fk_parent of table `test`.`child` trx id 34 lock_mode X waiting
      Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000002; asc         ;;
       1: len 8; hex 8000000000000002; asc         ;;
       
      *** CONFLICTING WITH:
      RECORD LOCKS space id 6 page no 4 n bits 320 index fk_parent of table `test`.`child` trx id 31 lock_mode X locks rec but not gap
      Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
       0: len 8; hex 8000000000000002; asc         ;;
       1: len 8; hex 8000000000000002; asc         ;;
       
      *** WE ROLL BACK TRANSACTION (1)
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 35
      Purge done for trx's n:o < 34 undo n:o < 0 state: running but idle
      History list length 1
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 31, ACTIVE 47 sec
      7 lock struct(s), heap size 1128, 8 row lock(s), undo log entries 4
      MariaDB thread id 3, OS thread handle 139687034406464, query id 27 172.20.0.1 root 
      ---TRANSACTION (0x7f0b573feb80), not started
      0 lock struct(s), heap size 1128, 0 row lock(s)
      --------
      FILE I/O
      --------
      Pending flushes (fsync): 0
      157 OS file reads, 0 OS file writes, 15 OS fsyncs
      0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.06 fsyncs/s
      ---
      LOG
      ---
      Log sequence number 59282
      Log flushed up to   59282
      Pages flushed up to 46846
      Last checkpoint at  46830
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total large memory allocated 167772160
      Dictionary memory allocated 859368
      Buffer pool size   8112
      Free buffers       7815
      Database pages     297
      Old database pages 0
      Modified db pages  41
      Percent of dirty pages(LRU & free pages): 0.505
      Max dirty pages percent: 90.000
      Pending reads 0
      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 149, created 148, written 0
      0.00 reads/s, 0.00 creates/s, 0.00 writes/s
      Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 297, 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
      ============================
      

      reports "WE ROLLBACK TRANSACTION (1)", where as "transaction 1" is the one with the `INSERT` (Connection #3, Query #27).

      InnoDB transaction rollback report is wrong.

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              arcivanov Arcadiy Ivanov
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated: