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

Long semaphore wait : deadlock in Innodb IO code, caused by change buffering.

    Details

      Description

      Full-log-file.txt Our Primary Live data factory at 05:25 started to hang

      We also have a SLAVE; with 0 seconds delay to master; and this experienced EXACTLY the same issue; and this Slave is on a totally different Virtual machine and different backend.

      When the problem started 05:25; user traffic and actual database activity was extremely low.

      new connections were able to logon to the database ok; but any activity against the INNODB database - datafactoryDB just hung and messages such as the below appeared in the MariaDB log files:-

      2018-03-28 5:25:50 2440 [Warning] InnoDB: A long semaphore wait:
      --Thread 1564 has waited at ibuf0ibuf.cc line 4394 for 241.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      2018-03-28 5:25:50 2440 [Warning] InnoDB: A long semaphore wait:
      --Thread 908 has waited at ibuf0ibuf.cc line 4578 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-03-28 5:25:50 2440 [Warning] InnoDB: A long semaphore wait:
      --Thread 4860 has waited at buf0buf.cc line 4136 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 04280A54 created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file buf0buf.cc line 4136
      Last time write locked in file buf0buf.cc line 5363
      2018-03-28 5:25:50 2440 [Warning] InnoDB: A long semaphore wait:
      --Thread 1480 has waited at ibuf0ibuf.cc line 4394 for 241.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      2018-03-28 5:25:50 2440 [Warning] InnoDB: A long semaphore wait:
      --Thread 1460 has waited at buf0buf.cc line 4136 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0CB3065C created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0sel.cc line 3568
      Last time write locked in file buf0buf.cc line 5363
      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 2448 has waited at ibuf0ibuf.cc line 2532 for 240.00 seconds the semaphore:
      S-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 1688 has waited at buf0flu.cc line 1246 for 232.00 seconds the semaphore:
      SX-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 1564 has waited at ibuf0ibuf.cc line 4394 for 241.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 908 has waited at ibuf0ibuf.cc line 4578 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 4860 has waited at buf0buf.cc line 4136 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 04280A54 created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file buf0buf.cc line 4136
      Last time write locked in file buf0buf.cc line 5363
      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 1480 has waited at ibuf0ibuf.cc line 4394 for 241.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      2018-03-28 5:25:50 2440 [Note] InnoDB: A semaphore wait:
      --Thread 1460 has waited at buf0buf.cc line 4136 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0CB3065C created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0sel.cc line 3568
      Last time write locked in file buf0buf.cc line 5363
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0

      =====================================
      2018-03-28 05:25:59 0x98c INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 64 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 37468 srv_active, 0 srv_shutdown, 56188 srv_idle
      srv_master_thread log flush and writes: 93655
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 626368
      --Thread 2448 has waited at ibuf0ibuf.cc line 2532 for 249.00 seconds the semaphore:
      S-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      --Thread 1688 has waited at buf0flu.cc line 1246 for 241.00 seconds the semaphore:
      SX-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      --Thread 1564 has waited at ibuf0ibuf.cc line 4394 for 250.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      --Thread 908 has waited at ibuf0ibuf.cc line 4578 for 250.00 seconds the semaphore:
      S-lock on RW-latch at 0431E114 created in file buf0buf.cc line 1471
      a writer (thread id 1460) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ibuf0ibuf.cc line 4578
      Last time write locked in file mtr0mtr.ic line 147
      --Thread 4860 has waited at buf0buf.cc line 4136 for 250.00 seconds the semaphore:
      S-lock on RW-latch at 04280A54 created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file buf0buf.cc line 4136
      Last time write locked in file buf0buf.cc line 5363
      --Thread 1480 has waited at ibuf0ibuf.cc line 4394 for 250.00 seconds the semaphore:
      Mutex at 01F93E20, Mutex IBUF created ibuf0ibuf.cc:516, lock var 2

      --Thread 1460 has waited at buf0buf.cc line 4136 for 250.00 seconds the semaphore:
      S-lock on RW-latch at 0CB3065C created in file buf0buf.cc line 1471
      a writer (thread id 0) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0sel.cc line 3568
      Last time write locked in file buf0buf.cc line 5363
      OS WAIT ARRAY INFO: signal count 520921
      RW-shared spins 0, rounds 798992, OS waits 390861
      RW-excl spins 0, rounds 1141727, OS waits 14298
      RW-sx spins 2663, rounds 33568, OS waits 503
      Spin rounds per wait: 798992.00 RW-shared, 1141727.00 RW-excl, 12.61 RW-sx
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 137843677
      Purge done for trx's n:o < 137843524 undo n:o < 0 state: running but idle
      History list length 15
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 281475041773368, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041772808, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041772248, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041771688, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041771128, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041770568, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041769448, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041768888, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041768328, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041759368, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041755448, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041753768, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041753208, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041739208, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041738088, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041725208, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041724088, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041767768, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041767208, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041766648, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041766088, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041765528, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041764968, not started
      0 lock struct(s), heap size 1080, 0 row lock(s)
      ---TRANSACTION 281475041764408, not started

        Attachments

        1. Full-log-file.txt
          225 kB
        2. mysqld.exe_180406_035217.zip
          428 kB
        3. stacks.txt
          23 kB

          Issue Links

            Activity

              People

              • Assignee:
                wlad Vladislav Vaintroub
                Reporter:
                slaterss Stuart Slater
              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: