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

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