[MDEV-15154] WSREP: BF lock wait long after a TRUNCATE TABLE Created: 2018-01-31  Updated: 2020-08-25  Resolved: 2018-07-25

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.2.12
Fix Version/s: 10.1.35, 10.2.17, 10.3.9

Type: Bug Priority: Critical
Reporter: Adrian Tarau Assignee: Jan Lindström (Inactive)
Resolution: Duplicate Votes: 6
Labels: innodb, wsrep
Environment:

innodb_version 5.7.20
protocol_version 10
slave_type_conversions
version 10.2.12-MariaDB
version_comment MariaDB Server
version_compile_machine x86_64
version_compile_os Linux
version_malloc_library system
version_ssl_library OpenSSL 1.0.1e-fips 11 Feb 2013
wsrep_patch_version wsrep_25.21

Attachments: File mysqld.log-20180327    
Issue Links:
Duplicate
duplicates MDEV-15822 WSREP: BF lock wait long for trx Closed
Relates
relates to MDEV-12837 WSREP: BF lock wait long Closed
relates to MDEV-13564 TRUNCATE TABLE and undo tablespace tr... Closed
relates to MDEV-14637 Latching order violation during btr_c... Closed
relates to MDEV-15855 Assertion `mysql_table' failed in inn... Closed

 Description   

This issue seems to be similar to MDEV-12837 (which was closed) and I was asked to open a new case.

Just like it is described in the other defect, once the log shows these waits, everything is locked. It looks like it is triggered by a TRUNCATE TABLE:

_LOCK WAIT
MySQL thread id 138641, OS thread handle 139936878089984, query id 139638795 ........ Opening tables
TRUNCATE TABLE `ds$etl_dimension_discovery_local_standard_1`
2018-01-24 11:51:38 139938787669760 [Note] InnoDB: WSREP: BF lock wait long for trx:0x1a3598f query: TRUNCATE TABLE `ds$etl_dimension_discovery_local_standard_1`
TRANSACTION 27482511, ACTIVE 1997 sec_

An email with logs was sent out to Jan Lindström ...if need it I can send the link again.

 Comments   
Comment by Adrian Tarau [ 2018-01-31 ]

Sorry, I had the wrong version, is 10.2.12, not 10.1.12 ... see the environment ...

Comment by Louis Chanouha [ 2018-02-06 ]

Happened 2 times since my cluster upgraded to 10.2.12, on a TRUNCATE query (both 2 cases).
I have a 3 nodes multi-master cluster, read/write are grouped on same server per database.

I think of rolling back to 10.2.11..

Feb 4 18:45:01 comue-db2 CRON[28228]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Feb 5 18:45:01 comue-db2 CRON[8851]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294869 trx_id: 318213882 seqnos (l: 2410254, g: 2439506, s: 2439504, d: 2439453, ts: 2265362460371980) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294870 trx_id: 318213883 seqnos (l: 2410255, g: 2439507, s: 2439504, d: 2439453, ts: 2265362460469831) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294869 trx_id: 318213886 seqnos (l: 2410256, g: 2439508, s: 2439504, d: 2439453, ts: 2265362460973025) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294870 trx_id: 318213887 seqnos (l: 2410257, g: 2439509, s: 2439504, d: 2439453, ts: 2265362461058064) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294869 trx_id: 318213890 seqnos (l: 2410258, g: 2439510, s: 2439504, d: 2439453, ts: 2265362461689955) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294870 trx_id: 318213891 seqnos (l: 2410259, g: 2439511, s: 2439504, d: 2439453, ts: 2265362461715411) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294870 trx_id: 318213894 seqnos (l: 2410260, g: 2439512, s: 2439504, d: 2439453, ts: 2265362462473094) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:34 comue-db2 mysqld[19481]: 2018-02-06 18:44:34 139873193645824 [Note] WSREP: trx conflict for key (0,FLAT8)c4e49158 db323286: source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 1 conn_id: 294869 trx_id: 318213895 seqnos (l: 2410261, g: 2439513, s: 2439504, d: 2439453, ts: 2265362462556279) <-X-> source: cb85a1a8-0817-11e8-9f55-96e13eb39a32 version: 3 local: 0 state: CERTIFYING flags: 65 conn_id: 294872 trx_id: -1 seqnos (l: 2410253, g: 2439505, s: 2439503, d: 2439504, ts: 2265362455033523)
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Note] InnoDB: *** Priority TRANSACTION:
Feb 6 18:44:36 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 0 sec
Feb 6 18:44:36 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:44:36 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Note] InnoDB: *** Victim TRANSACTION:
Feb 6 18:44:36 comue-db2 mysqld[19481]: TRANSACTION 318206960, ACTIVE 0 sec
Feb 6 18:44:36 comue-db2 mysqld[19481]: , undo log entries 8
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Note] InnoDB: *** WAITING FOR THIS LOCK TO BE GRANTED:
Feb 6 18:44:36 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 8 n bits 232 index PRIMARY of table `mysql`.`innodb_table_stats` trx id 318206960 lock_mode X locks rec but not gap
Feb 6 18:44:36 comue-db2 mysqld[19481]: Record lock, heap no 165 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
Feb 6 18:44:36 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 3: len 7; hex d60000035a0110; asc Z ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 4: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 5: len 8; hex 0000000000000001; asc ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 6: len 8; hex 0000000000000001; asc ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000002; asc ;;
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Note] InnoDB: SQL1: TRUNCATE cache_container
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Note] InnoDB: SQL2:
Feb 6 18:44:36 comue-db2 mysqld[19481]: 2018-02-06 18:44:36 139866394187520 [Warning] WSREP: no THD for trx: 318206960
Feb 6 18:45:01 comue-db2 CRON[19477]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Feb 6 18:45:27 comue-db2 mysqld[19481]: 2018-02-06 18:45:27 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:27 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 51 sec
Feb 6 18:45:27 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:27 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:27 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:28 comue-db2 mysqld[19481]: 2018-02-06 18:45:28 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:28 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 52 sec
Feb 6 18:45:28 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:28 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:28 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:29 comue-db2 mysqld[19481]: 2018-02-06 18:45:29 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:29 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 53 sec
Feb 6 18:45:29 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:29 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:29 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2018-02-06 18:45:30 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:30 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:30 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:30 comue-db2 mysqld[19481]: =====================================
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2018-02-06 18:45:30 0x7f353242e700 INNODB MONITOR OUTPUT
Feb 6 18:45:30 comue-db2 mysqld[19481]: =====================================
Feb 6 18:45:30 comue-db2 mysqld[19481]: Per second averages calculated from the last 56 seconds
Feb 6 18:45:30 comue-db2 mysqld[19481]: -----------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: BACKGROUND THREAD
Feb 6 18:45:30 comue-db2 mysqld[19481]: -----------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: srv_master_thread loops: 270967 srv_active, 0 srv_shutdown, 83907 srv_idle
Feb 6 18:45:30 comue-db2 mysqld[19481]: srv_master_thread log flush and writes: 354864
Feb 6 18:45:30 comue-db2 mysqld[19481]: ----------
Feb 6 18:45:30 comue-db2 mysqld[19481]: SEMAPHORES
Feb 6 18:45:30 comue-db2 mysqld[19481]: ----------
Feb 6 18:45:30 comue-db2 mysqld[19481]: OS WAIT ARRAY INFO: reservation count 2145614
Feb 6 18:45:30 comue-db2 mysqld[19481]: --Thread 139866478417664 has waited at srv0srv.cc line 2101 for 53.00 seconds the semaphore:
Feb 6 18:45:30 comue-db2 mysqld[19481]: Mutex at 0x55e769a618a0, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
Feb 6 18:45:30 comue-db2 mysqld[19481]: --Thread 139866444846848 has waited at dict0stats.cc line 2297 for 54.00 seconds the semaphore:
Feb 6 18:45:30 comue-db2 mysqld[19481]: Mutex at 0x55e769a618a0, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
Feb 6 18:45:30 comue-db2 mysqld[19481]: OS WAIT ARRAY INFO: signal count 1270846
Feb 6 18:45:30 comue-db2 mysqld[19481]: RW-shared spins 0, rounds 398633, OS waits 86088
Feb 6 18:45:30 comue-db2 mysqld[19481]: RW-excl spins 0, rounds 3448634, OS waits 65176
Feb 6 18:45:30 comue-db2 mysqld[19481]: RW-sx spins 71358, rounds 1244886, OS waits 21153
Feb 6 18:45:30 comue-db2 mysqld[19481]: Spin rounds per wait: 398633.00 RW-shared, 3448634.00 RW-excl, 17.45 RW-sx
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: LATEST FOREIGN KEY ERROR
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2018-02-02 16:28:54 0x7f352eab5700 Cannot drop table `xwiki`.`xwikiproperties`
Feb 6 18:45:30 comue-db2 mysqld[19481]: because it is referenced by `xwiki`.`xwikistrings`
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: TRANSACTIONS
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: Trx id counter 318206962
Feb 6 18:45:30 comue-db2 mysqld[19481]: Purge done for trx's n:o < 318206955 undo n:o < 0 state: running but idle
Feb 6 18:45:30 comue-db2 mysqld[19481]: History list length 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: LIST OF TRANSACTIONS FOR EACH SESSION:
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 421348440522264, not started
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0 lock struct(s), heap size 1136, 0 row lock(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206961, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:30 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------- TRX HAS BEEN WAITING 54 SEC FOR THIS LOCK TO BE GRANTED:
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 8 n bits 232 index PRIMARY of table "mysql"."innodb_table_stats" trx id 318206961 lock_mode X waiting
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 165 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 7; hex d60000035a0110; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000002; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: ------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "mysql"."innodb_table_stats" trx id 318206961 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 8 n bits 232 index PRIMARY of table "mysql"."innodb_table_stats" trx id 318206961 lock_mode X waiting
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 165 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 7; hex d60000035a0110; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000002; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206960, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 11 lock struct(s), heap size 1136, 15 row lock(s), undo log entries 8
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table `mysql`.`innodb_table_stats` trx id 318206960 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 8 n bits 232 index PRIMARY of table `mysql`.`innodb_table_stats` trx id 318206960 lock_mode X
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 8; hex 73757072656d756d; asc supremum;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 33 n bits 224 index PRIMARY of table `mysql`.`innodb_table_stats` trx id 318206960 lock_mode X
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 5 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 9; hex 636163686574616773; asc cachetags;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 6; hex 000012e7ef94; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 7; hex 2d0000036e016b; asc - n k;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 4; hex 5a795710; asc ZyW ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 8; hex 000000000000027f; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 8; hex 0000000000000004; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000000; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 1 page no 8 n bits 232 index PRIMARY of table `mysql`.`innodb_table_stats` trx id 318206960 lock_mode X locks gap before rec
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 165 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 7; hex d60000035a0110; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000002; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table `mysql`.`innodb_index_stats` trx id 318206960 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 2 page no 813 n bits 192 index PRIMARY of table `mysql`.`innodb_index_stats` trx id 318206960 lock_mode X
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 8; hex 73757072656d756d; asc supremum;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 2 page no 473 n bits 192 index PRIMARY of table `mysql`.`innodb_index_stats` trx id 318206960 lock_mode X
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 119 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 9; hex 636163686574616773; asc cachetags;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 5052494d415259; asc PRIMARY;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f646966665f7066783031; asc n_diff_pfx01;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012e7ef94; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex 2d0000036e025e; asc - n ^;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a795710; asc ZyW ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 000000000000027f; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: len 8; hex 0000000000000003; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 3; hex 746167; asc tag;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 2 page no 813 n bits 176 index PRIMARY of table `mysql`.`innodb_index_stats` trx id 318206960 lock_mode X locks gap before rec
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 110 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 5052494d415259; asc PRIMARY;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f646966665f7066783031; asc n_diff_pfx01;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a013e; asc Z >;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 3; hex 636964; asc cid;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 2 page no 814 n bits 72 index PRIMARY of table `mysql`.`innodb_index_stats` trx id 318206960 lock_mode X
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 8; hex 73757072656d756d; asc supremum;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: RECORD LOCKS space id 2 page no 814 n bits 72 index PRIMARY of table `mysql`.`innodb_index_stats` trx id 318206960 lock_mode X locks gap before rec
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 2 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 5052494d415259; asc PRIMARY;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f6c6561665f7061676573; asc n_leaf_pages;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a0181; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: SQL NULL;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 30; hex 4e756d626572206f66206c65616620706167657320696e2074686520696e; asc Number of leaf pages in the in; (total 33 bytes);
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 3 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 5052494d415259; asc PRIMARY;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 4; hex 73697a65; asc size;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a01c4; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: SQL NULL;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 28; hex 4e756d626572206f6620706167657320696e2074686520696e646578; asc Number of pages in the index;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 4 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 63726561746564; asc created;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f646966665f7066783031; asc n_diff_pfx01;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a01ff; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 7; hex 63726561746564; asc created;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 5 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 63726561746564; asc created;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f646966665f7066783032; asc n_diff_pfx02;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a0242; asc Z B;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 11; hex 637265617465642c636964; asc created,cid;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 6 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 63726561746564; asc created;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 12; hex 6e5f6c6561665f7061676573; asc n_leaf_pages;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a0285; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: SQL NULL;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 30; hex 4e756d626572206f66206c65616620706167657320696e2074686520696e; asc Number of leaf pages in the in; (total 33 bytes);
Feb 6 18:45:30 comue-db2 mysqld[19481]: Record lock, heap no 7 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0: len 22; hex 7765625f75745f64385f73697465696e73745f646576; asc web_ut_d8_siteinst_dev;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1: len 15; hex 63616368655f646973636f76657279; asc cache_discovery;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 2: len 7; hex 63726561746564; asc created;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3: len 4; hex 73697a65; asc size;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 4: len 6; hex 000012f773f0; asc s ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 5: len 7; hex d60000035a02c8; asc Z ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 6: len 4; hex 5a79e984; asc Zy ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 7: len 8; hex 0000000000000001; asc ;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 8: SQL NULL;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 9: len 28; hex 4e756d626572206f6620706167657320696e2074686520696e646578; asc Number of pages in the index;;
Feb 6 18:45:30 comue-db2 mysqld[19481]: 10 LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206958, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 21
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 13, OS thread handle 139873193645824, query id 4028668 applied write set 2439546
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table `web_ut_d8_siteinst_dev`.`cache_config` trx id 318206958 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206956, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 14, OS thread handle 139866394490624, query id 4028665 applied write set 2439545
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_default" trx id 318206956 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206955, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 9, OS thread handle 139866392975104, query id 4028664 applied write set 2439544
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_render" trx id 318206955 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206952, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 1, OS thread handle 139873468307200, query id 4028663 applied write set 2439543
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_render" trx id 318206952 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206950, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 15, OS thread handle 139866393581312, query id 4028662 applied write set 2439542
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_render" trx id 318206950 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206949, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 12, OS thread handle 139866393884416, query id 4028661 applied write set 2439541
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_render" trx id 318206949 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: ---TRANSACTION 318206947, ACTIVE 54 sec
Feb 6 18:45:30 comue-db2 mysqld[19481]: 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
Feb 6 18:45:30 comue-db2 mysqld[19481]: MySQL thread id 10, OS thread handle 139866393278208, query id 4028660 applied write set 2439540
Feb 6 18:45:30 comue-db2 mysqld[19481]: TABLE LOCK table "web_ut_d8_siteinst_dev"."cache_default" trx id 318206947 lock mode IX
Feb 6 18:45:30 comue-db2 mysqld[19481]: --------
Feb 6 18:45:30 comue-db2 mysqld[19481]: FILE I/O
Feb 6 18:45:30 comue-db2 mysqld[19481]: --------
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 1 state: waiting for completed aio requests (log thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 2 state: waiting for completed aio requests (read thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 3 state: waiting for completed aio requests (read thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 4 state: waiting for completed aio requests (read thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 5 state: waiting for completed aio requests (read thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 6 state: waiting for completed aio requests (write thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 7 state: waiting for completed aio requests (write thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 8 state: waiting for completed aio requests (write thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: I/O thread 9 state: waiting for completed aio requests (write thread)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
Feb 6 18:45:30 comue-db2 mysqld[19481]: ibuf aio reads:, log i/o's:, sync i/o's:
Feb 6 18:45:30 comue-db2 mysqld[19481]: Pending flushes (fsync) log: 0; buffer pool: 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: 49090 OS file reads, 5097301 OS file writes, 2516541 OS fsyncs
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0.00 reads/s, 0 avg bytes/read, 9.00 writes/s, 2.34 fsyncs/s
Feb 6 18:45:30 comue-db2 mysqld[19481]: -------------------------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: INSERT BUFFER AND ADAPTIVE HASH INDEX
Feb 6 18:45:30 comue-db2 mysqld[19481]: -------------------------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: Ibuf: size 1, free list len 96, seg size 98, 836 merges
Feb 6 18:45:30 comue-db2 mysqld[19481]: merged operations:
Feb 6 18:45:30 comue-db2 mysqld[19481]: insert 990, delete mark 3900, delete 215
Feb 6 18:45:30 comue-db2 mysqld[19481]: discarded operations:
Feb 6 18:45:30 comue-db2 mysqld[19481]: insert 0, delete mark 0, delete 0
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 36 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 53 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 11 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 23 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 13 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 8 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 22 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: Hash table size 1328051, node heap has 80 buffer(s)
Feb 6 18:45:30 comue-db2 mysqld[19481]: 3.18 hash searches/s, 19.55 non-hash searches/s
Feb 6 18:45:30 comue-db2 mysqld[19481]: —
Feb 6 18:45:30 comue-db2 mysqld[19481]: LOG
Feb 6 18:45:30 comue-db2 mysqld[19481]: —
Feb 6 18:45:30 comue-db2 mysqld[19481]: Log sequence number 161597342939
Feb 6 18:45:30 comue-db2 mysqld[19481]: Log flushed up to 161597342939
Feb 6 18:45:30 comue-db2 mysqld[19481]: Pages flushed up to 161597342939
Feb 6 18:45:30 comue-db2 mysqld[19481]: Last checkpoint at 161596378102
Feb 6 18:45:30 comue-db2 mysqld[19481]: 0 pending log flushes, 0 pending chkp writes
Feb 6 18:45:30 comue-db2 mysqld[19481]: 483214 log i/o's done, 0.23 log i/o's/second
Feb 6 18:45:30 comue-db2 mysqld[19481]: ----------------------
Feb 6 18:45:30 comue-db2 mysqld[19481]: BUFFER POOL AND MEMORY
Feb 6 18:45:30 comue-db2 mysqld[19481]: ----------------------
Feb 6 18:45:31 comue-db2 mysqld[19481]: 2018-02-06 18:45:31 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:31 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 55 sec
Feb 6 18:45:31 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:31 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:31 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:32 comue-db2 mysqld[19481]: 2018-02-06 18:45:32 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:32 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 56 sec
Feb 6 18:45:32 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:32 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:32 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:33 comue-db2 mysqld[19481]: 2018-02-06 18:45:33 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:33 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 57 sec
Feb 6 18:45:33 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:33 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:33 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:34 comue-db2 mysqld[19481]: 2018-02-06 18:45:34 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:34 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 58 sec
Feb 6 18:45:34 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:34 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:34 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:35 comue-db2 mysqld[19481]: 2018-02-06 18:45:35 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:35 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 59 sec
Feb 6 18:45:35 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:35 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:35 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:36 comue-db2 mysqld[19481]: 2018-02-06 18:45:36 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:36 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 60 sec
Feb 6 18:45:36 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:36 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:36 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:37 comue-db2 mysqld[19481]: 2018-02-06 18:45:37 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:37 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 61 sec
Feb 6 18:45:37 comue-db2 mysqld[19481]: LOCK WAIT
Feb 6 18:45:37 comue-db2 mysqld[19481]: MySQL thread id 11, OS thread handle 139866394187520, query id 4028667 Opening tables
Feb 6 18:45:37 comue-db2 mysqld[19481]: TRUNCATE cache_container
Feb 6 18:45:38 comue-db2 mysqld[19481]: 2018-02-06 18:45:38 139866470024960 [Note] InnoDB: WSREP: BF lock wait long for trx:0x12f773f1 query: TRUNCATE cache_container
Feb 6 18:45:38 comue-db2 mysqld[19481]: TRANSACTION 318206961, ACTIVE 62 sec
Feb 6 18:45:38 comue-db2 mysqld[19481]: LOCK WAIT

Comment by Adrian Tarau [ 2018-02-06 ]

Same here, 3 mode cluster with HAProxy, writes are passed to the active node.... A TRUNCATE TABLE at the wrong time and the cluster (writer node) locks itself ...

Comment by Louis Chanouha [ 2018-02-07 ]

I'm looking for mariadb-server-10.2_10.2.11~maria~jessie_amd64.deb and mariadb-server-core-10.2_10.2.11~maria~jessie_amd64.deb to test on earlier version ? Someone know where i can found Debian package archives ?

Comment by Neil Skrypuch [ 2018-02-09 ]

Also seeing this in our environment. #12837 seems to have fixed the issue for DML queries, but not DDL queries. All instances of this issue since updating to 10.2.12 have been with only DDL queries, whereas before we were seeing it with DML queries.

Comment by manu [ 2018-02-10 ]

I got a similar issue in 10.2.12 on debian 9

2018-02-10 0:29:59 140172996368128 [Note] InnoDB: *** Priority TRANSACTION:
TRANSACTION 5060635, ACTIVE 0 sec
MySQL thread id 609526, OS thread handle 140172996368128, query id 5222696 172.31.250.20 mybdd creating table
CREATE TABLE t1 LIKE t2
2018-02-10 0:29:59 140172996368128 [Note] InnoDB: *** Victim TRANSACTION:
TRANSACTION 5060634, ACTIVE 0 sec
, undo log entries 8
2018-02-10 0:29:59 140172996368128 [Note] InnoDB: *** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1 page no 19 n bits 200 index PRIMARY of table `mysql`.`innodb_table_stats` trx id 5060634 lock_mode X
Record lock, heap no 43 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
0: len 25; hex 6e6574776f726b6d616e616765725f6d6f6e69746f72696e67; asc mybdd2;;
1: len 15; hex 6d6f6e69746f72696e675f64696167; asc t3;;
2: len 6; hex 0000004d381a; asc M8 ;;
3: len 7; hex 06000100071a0e; asc ;;
4: len 4; hex 5a7e2ef7; asc Z~. ;;
5: len 8; hex 000000000000013d; asc =;;
6: len 8; hex 000000000000000c; asc ;;
7: len 8; hex 0000000000000001; asc ;;

Record lock, heap no 45 PHYSICAL RECORD: n_fields 8; compact format; info bits 0
0: len 25; hex 6e6574776f726b6d616e616765725f6d6f6e69746f72696e67; asc mybdd2;;
1: len 25; hex 6d6f6e69746f72696e675f70726f78795f6c6973745f75726c; asc t4;;
2: len 6; hex 0000003da0b5; asc = ;;
3: len 7; hex 750000027e1031; asc u ~ 1;;
4: len 4; hex 5a7ddb31; asc Z} 1;;
5: len 8; hex 000000000067f269; asc g i;;
6: len 8; hex 000000000000e100; asc ;;
7: len 8; hex 0000000000010fc0; asc ;;

2018-02-10 0:29:59 140172996368128 [Note] InnoDB: SQL1: CREATE TABLE t1 LIKE t2
2018-02-10 0:29:59 140172996368128 [Note] InnoDB: SQL2:
2018-02-10 0:29:59 140172996368128 [Warning] WSREP: no THD for trx: 5060634
2018-02-10 0:30:50 140172994914048 [Note] InnoDB: WSREP: BF lock wait long for trx:0x4d381b query: CREATE TABLE t1 LIKE t2
TRANSACTION 5060635, ACTIVE 51 sec
LOCK WAIT
MySQL thread id 609526, OS thread handle 140172996368128, query id 5222696 172.31.250.20 mybdd creating table
CREATE TABLE t1 LIKE t2

Comment by Louis Chanouha [ 2018-02-13 ]

I didn't get any lock since i rollbacked to 10.2.11 some days ago.
Seems to be a regression in 10.2.12, but test period is still too short to confirm.

Comment by Louis Chanouha [ 2018-02-27 ]

I still had no crash since my rollback to 10.2.11. Someone got any news about this issue ?

Comment by Jan Lindström (Inactive) [ 2018-03-01 ]

Do you have full error log and could you enable wsrep_debug ?

Comment by Reinhard Sojka [ 2018-04-06 ]

We ran in this bug last week, but I had no time to look deeper into this until now.
It was a Cluster with 2 nodes running on 10.2.12. After restarting the stalled node, everything was fine.

OS was CentOS 7.4 with microcode_ctl-2.1-22.2.el7.x86_64, which was withdrawn

mysqld.log-20180327

Comment by Ranjan Ghosh [ 2018-04-23 ]

Just happened on our cluster as well. Since the infamous MDEV-12837 has thankfully been solved, the BF lock wait long error seems to have become really rare, fortunately. I haven't had a crash for a few months. Before, the cluster came down multiple times a day. Nevertheless still seems to happen. And, like the other reports, our log also says something about a TRUNCATE operation causing the problem. Another difference I noticed is that back then the lock always happend on our primary server (where all the requests where routed to). Now, the second server seems to have come down and block the first one. I still wonder whether it wouldnt be a good idea to just automatically shutdown the server as soon as this message occurs. It seems to be as soon as BF lock wait long appears in the log the server is irrevocably lost until it's restarted. Is there any use to keep it running? Automatic shutdown would prevent this error to take the whole cluster with it which is the main thing why it's so evil.

Apr 20 15:07:20 tukan2 mysqld[1555]: 2018-04-20 15:07:20 140472215070464 [Warning] WSREP: no THD for trx: 21799700005
 
Apr 20 15:08:11 tukan2 mysqld[1555]: 2018-04-20 15:08:11 140472599467776 [Note] InnoDB: WSREP: BF lock wait long for trx:0x5135d0626 query: TRUNCATE cache_discovery
 
Apr 20 15:08:11 tukan2 mysqld[1555]: TRANSACTION 21799700006, ACTIVE 51 sec
 
Apr 20 15:08:11 tukan2 mysqld[1555]: LOCK WAIT
 
Apr 20 15:08:11 tukan2 mysqld[1555]: MySQL thread id 30, OS thread handle 140472215070464, query id 38658230 Opening tables
 
Apr 20 15:08:11 tukan2 mysqld[1555]: TRUNCATE cache_discovery
 
Apr 20 15:08:12 tukan2 mysqld[1555]: 2018-04-20 15:08:12 140472599467776 [Note] InnoDB: WSREP: BF lock wait long for trx:0x5135d0626 query: TRUNCATE cache_discovery
 
Apr 20 15:08:12 tukan2 mysqld[1555]: TRANSACTION 21799700006, ACTIVE 52 sec
 
Apr 20 15:08:12 tukan2 mysqld[1555]: LOCK WAIT
 
Apr 20 15:08:12 tukan2 mysqld[1555]: MySQL thread id 30, OS thread handle 140472215070464, query id 38658230 Opening tables
 
Apr 20 15:08:12 tukan2 mysqld[1555]: TRUNCATE cache_discovery
 
Apr 20 15:08:13 tukan2 mysqld[1555]: 2018-04-20 15:08:13 140472599467776 [Note] InnoDB: WSREP: BF lock wait long for trx:0x5135d0626 query: TRUNCATE cache_discovery
 
Apr 20 15:08:13 tukan2 mysqld[1555]: TRANSACTION 21799700006, ACTIVE 53 sec
 
Apr 20 15:08:13 tukan2 mysqld[1555]: LOCK WAIT

Comment by Ranjan Ghosh [ 2018-05-30 ]

Just had another catastrophic failure. I wonder: Is there at least any progress/news on this issue? Obviously not so cool to have a cluster completely grinding to a halt once per month...

Comment by Marko Mäkelä [ 2018-07-05 ]

I believe that this bug may be related to the WL#6501 TRUNCATE TABLE rewrite in MySQL 5.7, which was merged to MariaDB Server 10.2.

If we implemented TRUNCATE TABLE as a combination of RENAME TABLE, CREATE TABLE and DROP TABLE, that should address not only this problem, but the related backup problem that is mentioned in MDEV-13564. We do not have crash-safe RENAME before MariaDB 10.3, so we may need a different type of a fix for 10.2.

Comment by Marko Mäkelä [ 2018-07-05 ]

This issue may also be a duplicate of MDEV-15855.

Comment by Adrian Tarau [ 2018-07-06 ]

Should I presume the problem does not exist in 10.3?

Comment by Marko Mäkelä [ 2018-07-06 ]

adrian.tarau, I would be very surprised if this problem did not exist in 10.3. If anyone experienced this problem without using indexed virtual columns (MDEV-5800), then this issue cannot be a duplicate of MDEV-15855. MDEV-15855 can cause InnoDB hangs, but only when indexed virtual columns are used.

Another known source of InnoDB hangs in MariaDB 10.2 and later is MDEV-14637. Those hangs should be possible even without involving TRUNCATE TABLE.

InnoDB hangs are easiest to diagnose based on stack traces of all threads. Something like the following should do the trick:

echo 'thread apply all backtrace;detach'|gdb -p $(pgrep -x mysqld) > gdb.txt

Comment by Ranjan Ghosh [ 2018-07-06 ]

Right. We don't use virtual columns at all. Still the database crashes.

Comment by Adrian Tarau [ 2018-07-06 ]

Same here ... No virtual columns...

Comment by Louis Chanouha [ 2018-07-07 ]

Same, i don't use virtuals columns.

Pretty sure regression appreared in 10.2.12
I use 10.2.11 since january without any problems since i downgraded from 10.2.12.

Comment by Adrian Tarau [ 2018-07-08 ]

Same here, 10.2.11 seems stable... I would like to move to 10.3 for several reasons... but....an issue that would make things slower or fail once in a while would not be a major issue.. but if the whole database locks, that's another story.

Comment by Ranjan Ghosh [ 2018-07-08 ]

Well, just for the record: 10.2.11 was unfortunately extremely unstable for us due to MDEV-12837. Our database crashed with BF lock wait nearly every day. Totally unusable. Now we have this bug, which "only" crashes the database once per month. I also wouldnt have a problem if the database really crashed. The problem with the "BF lock wait" bug class is: The whole cluster locks up completely. New queries start piling up, overloading the server. And when you recognize the problem, it is sometimes very difficult to resolve it. Sometimes I had to kill both databases. Then I tried to start the first one. Didnt work. I tried to start the other one. Did work. Then you have to start the second to have the full cluster back online. Doesnt work - cannot re-sync. Then I delete the /var/lib/mysql folder. Now the second database starts, does a full sync. During the sync the other database is of course in DONOR/DSYNC state as usual for 10 minutes. After that, everything is finally OK. Not a every nice experience at all and difficult to explain to my coworkers who are not that Admin-savvy. Honestly, after waiting so many months for MDEV-12837 to be resolved and now this bug, I'm not really looking forward to an upgrade for 10.3 with new potential problems. I'd much prefer to have a really stable 10.2 version which you can really use in production with Galera.

Comment by Rasmus Johansson (Inactive) [ 2018-07-19 ]

jplindst If you can repeat this, could you test if the fix of MDEV-15855 helped here as well?

Comment by Jan Lindström (Inactive) [ 2018-07-25 ]

Hi, do you use persistent statistics? Please provide show create table from cf_cache_imagesizes_tags and configuration files.

Comment by Jan Lindström (Inactive) [ 2018-07-25 ]

Fixed by:

ommit 57cde8ccd19675dc98e3cbacf0ef5c72cb188e49 (HEAD -> 10.1, origin/10.1)
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Jul 25 08:21:25 2018 +0300

MDEV-15822: WSREP: BF lock wait long for trx

In Galera BF (brute force) transactions may not wait for lock requests
and normally BF-transaction would select transaction holding conflicting
locks as a victim for rollback. However, background statistic calculation
transaction is InnoDB internal transaction and it has no thd i.e. it can't be
selected as a victim. If background statistics calculation transaction holds
conflicting locks to statistics tables it will cause BF lock wait long
error message. Correct way to handle background statistics calculation is to
acquire thd for transaction but that change is too big for GA-releases and
there are other reported problems on background statistics calculation.

This fix avoids adding a table to background statistics calculation if

Generated at Thu Feb 08 08:19:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.