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

parallel replication lock contention with DDL/DML on slave

    XMLWordPrintable

    Details

      Description

      This slave wasn't resolving its locks:

      Trx total rec lock wait time 12700 SEC on some of the parallel threads:

      MariaDB [hotspot]> CREATE TABLE UserExpiry SELECT Location, Expire FROM UserInfo;
      ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

      MariaDB [hotspot]> SHOW ENGINE INNODB STATUS\G
      *************************** 1. row ***************************
        Type: InnoDB
        Name: 
      Status: 
      =====================================
      2015-03-25 13:36:21 7f96d3bf4700 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 1 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 588997 srv_active, 0 srv_shutdown, 3166 srv_idle
      srv_master_thread log flush and writes: 592163
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 15337153
      OS WAIT ARRAY INFO: signal count 13206239
      Mutex spin waits 42778016, rounds 498035174, OS waits 12195640
      RW-shared spins 3104395, rounds 65795945, OS waits 1890737
      RW-excl spins 3332601, rounds 52029014, OS waits 744942
      Spin rounds per wait: 11.64 mutex, 21.19 RW-shared, 15.61 RW-excl
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 2374048291
      Purge done for trx's n:o < 2374048291 undo n:o < 0 state: running but idle
      History list length 1224
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 2374048272, not started
      MySQL thread id 377135, OS thread handle 0x7f9776c6b700, query id 117572064 223.27.66.13 overseer cleaning up
      ---TRANSACTION 2374048178, not started
      MySQL thread id 373677, OS thread handle 0x7f96e346b700, query id 117571821 223.27.66.13 root cleaning up
      ---TRANSACTION 0, not started
      MySQL thread id 371257, OS thread handle 0x7f96d3bf4700, query id 117572115 223.27.66.13 root init
      SHOW ENGINE INNODB STATUS
      ---TRANSACTION 0, not started
      MySQL thread id 371180, OS thread handle 0x7f971446b700, query id 117571987 223.27.66.13 root cleaning up
      ---TRANSACTION 2332704790, not started
      MySQL thread id 97948, OS thread handle 0x7f96c53ab700, query id 0 Waiting for master to send event
      ---TRANSACTION 2374048234, not started
      MySQL thread id 7, OS thread handle 0x7f96c52d0700, query id 117571901 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374048203, not started
      MySQL thread id 4, OS thread handle 0x7f96c51f5700, query id 117571860 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374048246, not started
      MySQL thread id 19, OS thread handle 0x7f96c5163700, query id 117571919 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374048238, not started
      MySQL thread id 11, OS thread handle 0x7f96c51ac700, query id 117571905 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374048247, not started
      MySQL thread id 9, OS thread handle 0x7f96c5088700, query id 117571921 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374048245, not started
      MySQL thread id 21, OS thread handle 0x7f980a86b700, query id 117571917 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2374047856, not started
      MySQL thread id 18, OS thread handle 0x7f983bc48700, query id 117571289 Waiting for prior transaction to start commit before starting next transaction
      ---TRANSACTION 2318180099, not started
      MySQL thread id 1, OS thread handle 0x7f96bc9fe700, query id 0 Waiting for background binlog tasks
      ---TRANSACTION 2374048288, ACTIVE (PREPARED) 0 sec
      4 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 2
      MySQL thread id 22, OS thread handle 0x7f9872d03700, query id 117572113 Waiting for prior transaction to commit
      Trx #rec lock waits 159407 #table lock waits 142
      Trx total rec lock wait time 12567 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."UserInfo" trx id 2374048288 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 1620 n bits 480 index "UserName" of table "hotspot"."UserInfo" trx table locks 2 total table locks 5  trx id 2374048288 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 1198 n bits 112 index "PRIMARY" of table "hotspot"."UserInfo" trx table locks 2 total table locks 5  trx id 2374048288 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048288 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048285, ACTIVE (PREPARED) 0 sec
      6 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 4
      MySQL thread id 3, OS thread handle 0x7f96c523e700, query id 117572111 Waiting for prior transaction to commit
      Trx #rec lock waits 160163 #table lock waits 146
      Trx total rec lock wait time 12561 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radusage" trx id 2374048285 lock mode IX lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."UserInfo" trx id 2374048285 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 1193 n bits 112 index "PRIMARY" of table "hotspot"."UserInfo" trx table locks 4 total table locks 5  trx id 2374048285 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."radacct" trx id 2374048285 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11949 page no 138621 n bits 136 index "PRIMARY" of table "hotspot"."radacct" trx table locks 4 total table locks 5  trx id 2374048285 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048285 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048284, ACTIVE 0 sec inserting
      mysql tables in use 1, locked 1
      LOCK WAIT 2 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 1
      MySQL thread id 14, OS thread handle 0x7f9872dde700, query id 117572106 update
      REPLACE INTO radcheck (username, attribute, op, value) VALUES ('NOTREALUSER', 'password', ':=', 'NOTREALPASSWORD')
      Trx #rec lock waits 159198 #table lock waits 137
      Trx total rec lock wait time 12568 SEC
      Trx total table lock wait time 0 SEC
      ------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
      RECORD LOCKS space id 199 page no 868 n bits 832 index "UserName" of table "hotspot"."radcheck" trx table locks 1 total table locks 3  trx id 2374048284 lock_mode X locks gap before rec insert intention waiting lock hold time 0 wait time before grant 0 
      ------------------
      TABLE LOCK table "hotspot"."radcheck" trx id 2374048284 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 199 page no 868 n bits 832 index "UserName" of table "hotspot"."radcheck" trx table locks 1 total table locks 3  trx id 2374048284 lock_mode X locks gap before rec insert intention waiting lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048283, ACTIVE (PREPARED) 0 sec
      3 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 2
      MySQL thread id 15, OS thread handle 0x7f9872d4c700, query id 117572104 Waiting for prior transaction to commit
      Trx #rec lock waits 160406 #table lock waits 150
      Trx total rec lock wait time 12689 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."active_sessions" trx id 2374048283 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 152 page no 10110 n bits 80 index "PRIMARY" of table "hotspot"."active_sessions" trx table locks 2 total table locks 1  trx id 2374048283 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048283 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048282, ACTIVE (PREPARED) 0 sec
      5 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 2
      MySQL thread id 12, OS thread handle 0x7f96c5287700, query id 117572102 Waiting for prior transaction to commit
      Trx #rec lock waits 159927 #table lock waits 139
      Trx total rec lock wait time 12700 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radcheck" trx id 2374048282 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 199 page no 533 n bits 664 index "UserName" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048282 lock_mode X lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 199 page no 1179 n bits 160 index "PRIMARY" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048282 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 199 page no 533 n bits 664 index "UserName" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048282 lock_mode X locks gap before rec lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048282 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048281, ACTIVE (PREPARED) 0 sec
      5 lock struct(s), heap size 1184, 7 row lock(s), undo log entries 4
      MySQL thread id 20, OS thread handle 0x7f986f86f700, query id 117572100 closing tables
      Trx #rec lock waits 158976 #table lock waits 157
      Trx total rec lock wait time 12524 SEC
      Trx total table lock wait time 1 SEC
      TABLE LOCK table `hotspot`.`radreply` trx id 2374048281 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11812 page no 599 n bits 752 index `UserName` of table `hotspot`.`radreply` trx table locks 2 total table locks 2  trx id 2374048281 lock_mode X lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11812 page no 138 n bits 304 index `PRIMARY` of table `hotspot`.`radreply` trx table locks 2 total table locks 2  trx id 2374048281 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11812 page no 599 n bits 752 index `UserName` of table `hotspot`.`radreply` trx table locks 2 total table locks 2  trx id 2374048281 lock_mode X locks gap before rec lock hold time 0 wait time before grant 0 
      TABLE LOCK table `mysql`.`gtid_slave_pos` trx id 2374048281 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048280, ACTIVE (PREPARED) 0 sec
      7 lock struct(s), heap size 1184, 5 row lock(s), undo log entries 7
      MySQL thread id 5, OS thread handle 0x7f96c5362700, query id 117572098 closing tables
      Trx #rec lock waits 158864 #table lock waits 153
      Trx total rec lock wait time 12568 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radusage" trx id 2374048280 lock mode IX lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."UserInfo" trx id 2374048280 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 1148 n bits 112 index "PRIMARY" of table "hotspot"."UserInfo" trx table locks 4 total table locks 5  trx id 2374048280 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."radacct" trx id 2374048280 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11949 page no 135350 n bits 144 index "PRIMARY" of table "hotspot"."radacct" trx table locks 4 total table locks 5  trx id 2374048280 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048280 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 6112 page no 3 n bits 336 index "PRIMARY" of table "mysql"."gtid_slave_pos" trx table locks 4 total table locks 12  trx id 2374048280 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048276, ACTIVE (PREPARED) 0 sec
      6 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 4
      MySQL thread id 13, OS thread handle 0x7f9872d95700, query id 117572093 Waiting for prior transaction to commit
      Trx #rec lock waits 159427 #table lock waits 145
      Trx total rec lock wait time 12551 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radusage" trx id 2374048276 lock mode IX lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."UserInfo" trx id 2374048276 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 509 n bits 104 index "PRIMARY" of table "hotspot"."UserInfo" trx table locks 4 total table locks 5  trx id 2374048276 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "hotspot"."radacct" trx id 2374048276 lock mode IX lock hold time 0 wait time before grant 0 
      RECORD LOCKS space id 11949 page no 138781 n bits 136 index "PRIMARY" of table "hotspot"."radacct" trx table locks 4 total table locks 5  trx id 2374048276 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048276 lock mode IX lock hold time 0 wait time before grant 0 
      ---TRANSACTION 2374048253, ACTIVE (PREPARED) 51 sec
      3 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 2
      MySQL thread id 10, OS thread handle 0x7f9872e27700, query id 117571943 Waiting for prior transaction to commit
      Trx #rec lock waits 159074 #table lock waits 147
      Trx total rec lock wait time 12529 SEC
      Trx total table lock wait time 1 SEC
      TABLE LOCK table "hotspot"."radacct" trx id 2374048253 lock mode IX lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 11949 page no 127327 n bits 136 index "PRIMARY" of table "hotspot"."radacct" trx table locks 2 total table locks 5  trx id 2374048253 lock_mode X locks rec but not gap lock hold time 51 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048253 lock mode IX lock hold time 51 wait time before grant 0 
      ---TRANSACTION 2374048252, ACTIVE (PREPARED) 51 sec
      3 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 1
      MySQL thread id 17, OS thread handle 0x7f9872cba700, query id 117571938 Waiting for prior transaction to commit
      COMMIT
      Trx #rec lock waits 159652 #table lock waits 145
      Trx total rec lock wait time 12876 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."badauth_counts" trx id 2374048252 lock mode IX lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 2864 page no 5 n bits 160 index "username" of table "hotspot"."badauth_counts" trx table locks 2 total table locks 1  trx id 2374048252 lock_mode X locks gap before rec lock hold time 51 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048252 lock mode IX lock hold time 51 wait time before grant 0 
      ---TRANSACTION 2374048251, ACTIVE (PREPARED) 51 sec
      6 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 4
      MySQL thread id 6, OS thread handle 0x7f96c511a700, query id 117571935 Waiting for prior transaction to commit
      Trx #rec lock waits 159091 #table lock waits 152
      Trx total rec lock wait time 12655 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radusage" trx id 2374048251 lock mode IX lock hold time 51 wait time before grant 0 
      TABLE LOCK table "hotspot"."UserInfo" trx id 2374048251 lock mode IX lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 15794 page no 1216 n bits 104 index "PRIMARY" of table "hotspot"."UserInfo" trx table locks 4 total table locks 5  trx id 2374048251 lock_mode X locks rec but not gap lock hold time 51 wait time before grant 0 
      TABLE LOCK table "hotspot"."radacct" trx id 2374048251 lock mode IX lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 11949 page no 138773 n bits 136 index "PRIMARY" of table "hotspot"."radacct" trx table locks 4 total table locks 5  trx id 2374048251 lock_mode X locks rec but not gap lock hold time 51 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048251 lock mode IX lock hold time 51 wait time before grant 0 
      ---TRANSACTION 2374048249, ACTIVE (PREPARED) 51 sec
      2 lock struct(s), heap size 360, 0 row lock(s), undo log entries 2
      MySQL thread id 8, OS thread handle 0x7f96c50d1700, query id 117571928 Waiting for prior transaction to commit
      Trx #rec lock waits 159554 #table lock waits 148
      Trx total rec lock wait time 12522 SEC
      Trx total table lock wait time 1 SEC
      TABLE LOCK table "hotspot"."radreply" trx id 2374048249 lock mode IX lock hold time 51 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048249 lock mode IX lock hold time 51 wait time before grant 0 
      ---TRANSACTION 2374048248, ACTIVE (PREPARED) 51 sec
      5 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 2
      MySQL thread id 16, OS thread handle 0x7f96c5319700, query id 117571926 Waiting for prior transaction to commit
      Trx #rec lock waits 159396 #table lock waits 168
      Trx total rec lock wait time 12611 SEC
      Trx total table lock wait time 0 SEC
      TABLE LOCK table "hotspot"."radcheck" trx id 2374048248 lock mode IX lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 199 page no 868 n bits 832 index "UserName" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048248 lock_mode X lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 199 page no 1179 n bits 160 index "PRIMARY" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048248 lock_mode X locks rec but not gap lock hold time 51 wait time before grant 0 
      RECORD LOCKS space id 199 page no 868 n bits 832 index "UserName" of table "hotspot"."radcheck" trx table locks 2 total table locks 3  trx id 2374048248 lock_mode X locks gap before rec lock hold time 51 wait time before grant 0 
      TABLE LOCK table "mysql"."gtid_slave_pos" trx id 2374048248 lock mode IX lock hold time 51 wait time before grant 0 
      --------
      FILE I/O
      --------

      binlog and more detailed information in private upload (two files)

        Attachments

          Activity

            People

            Assignee:
            knielsen Kristian Nielsen
            Reporter:
            danblack Daniel Black
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:

                Git Integration