[MDEV-15354] [Draft] Deadlock and long semaphore wait Created: 2018-02-19  Updated: 2018-04-07

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Elena Stepanova
Resolution: Unresolved Votes: 1
Labels: None

Attachments: HTML File threads    

 Description   

https://api.travis-ci.org/v3/job/343174384/log.txt

10.3 afc56a509cc7d3d651ca68ad826ca183da8dc7cc

 
2018-02-19  2:21:33 0 [Warning] No argument was provided to --log-bin and neither --log-basename or --log-bin-index where used;  This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '--log-basename=travis-job-2c04e288-c888-4f72-9854-d0be989b4aa8' or '--log-bin=mysql-bin' to avoid this problem.
 
Version: '10.3.5-MariaDB-debug-log'  socket: '/home/travis/logs/vardir1_1/mysql.sock'  port: 19300  Source distribution
 
2018-02-19  2:22:17 18 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave Statement: OPTIMIZE TABLE t2 /* QNO 407 CON_ID 18 */
 
2018-02-19  2:29:56 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 241.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
2018-02-19  2:29:56 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 241.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 241.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
--Thread 140046884914944 has waited at dict0dict.cc line 1162 for 153.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046537799424 has waited at dict0dict.cc line 1162 for 186.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 217.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538102528 has waited at dict0dict.cc line 498 for 156.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 241.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
=====================================
 
2018-02-19 02:30:14 0x7f5f0c9f4700 INNODB MONITOR OUTPUT
 
=====================================
 
Per second averages calculated from the last 32 seconds
 
-----------------
 
BACKGROUND THREAD
 
-----------------
 
srv_master_thread loops: 58 srv_active, 0 srv_shutdown, 201 srv_idle
 
srv_master_thread log flush and writes: 258
 
----------
 
SEMAPHORES
 
----------
 
-------------
 
RW-LATCH INFO
 
-------------
 
RW-LOCK: 0x5580c8f59680  (1 waiters)
 
Locked: thread 140046885218048 file row0mysql.cc line 4191  X-LOCK
 
Total number of rw-locks 16528
 
OS WAIT ARRAY INFO: reservation count 7392
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 259.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
--Thread 140046884914944 has waited at dict0dict.cc line 1162 for 171.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046537799424 has waited at dict0dict.cc line 1162 for 204.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 235.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538102528 has waited at dict0dict.cc line 498 for 174.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 259.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
OS WAIT ARRAY INFO: signal count 3547
 
RW-shared spins 0, rounds 1552, OS waits 714
 
RW-excl spins 0, rounds 5919, OS waits 253
 
RW-sx spins 3, rounds 9, OS waits 0
 
Spin rounds per wait: 1552.00 RW-shared, 5919.00 RW-excl, 3.00 RW-sx
 
------------------------
 
LATEST DETECTED DEADLOCK
 
------------------------
 
2018-02-19 02:23:08 0x7f5f202c7700
 
*** (1) TRANSACTION:
 
TRANSACTION 23245, ACTIVE 0 sec inserting
 
mysql tables in use 1, locked 1
 
LOCK WAIT 4 lock struct(s), heap size 1160, 7 row lock(s), undo log entries 6
 
MySQL thread id 33, OS thread handle 140046884914944, query id 6396 localhost 127.0.0.1 rqg Reading file
 
LOAD DATA INFILE 'load_table10_int' REPLACE INTO TABLE table10_int /* QNO 726 CON_ID 17 */
 
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
 
RECORD LOCKS space id 72 page no 3 n bits 96 index PRIMARY of table `test`.`table10_int` trx id 23245 lock_mode X waiting
 
Record lock, heap no 5 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 
 0: len 4; hex 80000004; asc     ;;
 
 1: len 7; hex 7fffffff0f423f; asc      B?;;
 
 2: len 6; hex 000000000000; asc       ;;
 
 3: len 7; hex 80000000000000; asc        ;;
 
 4: SQL NULL;
 
 5: SQL NULL;
 
 6: len 7; hex 5a8a350c00e256; asc Z 5   V;;
 
*** (2) TRANSACTION:
 
TRANSACTION 23232, ACTIVE 0 sec inserting
 
mysql tables in use 1, locked 1
 
7 lock struct(s), heap size 1160, 13 row lock(s), undo log entries 30
 
MySQL thread id 29, OS thread handle 140046538405632, query id 6461 localhost 127.0.0.1 rqg Reading file
 
LOAD DATA INFILE 'load_table10_int' IGNORE INTO TABLE table10_int /* QNO 1784 CON_ID 16 */
 
*** (2) HOLDS THE LOCK(S):
 
RECORD LOCKS space id 72 page no 3 n bits 88 index PRIMARY of table `test`.`table10_int` trx id 23232 lock mode S
 
Record lock, heap no 5 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 
 0: len 4; hex 80000004; asc     ;;
 
 1: len 7; hex 7fffffff0f423f; asc      B?;;
 
 2: len 6; hex 000000000000; asc       ;;
 
 3: len 7; hex 80000000000000; asc        ;;
 
 4: SQL NULL;
 
 5: SQL NULL;
 
 6: len 7; hex 5a8a350c00e256; asc Z 5   V;;
 
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
 
RECORD LOCKS space id 72 page no 3 n bits 96 index PRIMARY of table `test`.`table10_int` trx id 23232 lock mode S waiting
 
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 
 0: len 4; hex 80000001; asc     ;;
 
 1: len 7; hex 7fffffff0f423f; asc      B?;;
 
 2: len 6; hex 000000005acd; asc     Z ;;
 
 3: len 7; hex 300000015805a3; asc 0   X  ;;
 
 4: SQL NULL;
 
 5: len 4; hex b2820000; asc     ;;
 
 6: len 7; hex 5a8a350c03272f; asc Z 5  '/;;
 
*** WE ROLL BACK TRANSACTION (1)
 
------------
 
TRANSACTIONS
 
------------
 
Trx id counter 4089434
 
Purge done for trx's n:o < 23635 undo n:o < 0 state: running but idle
 
History list length 276
 
Total number of lock structs in row lock hash table 5
 
LIST OF TRANSACTIONS FOR EACH SESSION:
 
---TRANSACTION 421521862852104, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862845048, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862848576, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862843872, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862847400, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862842696, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 421521862841520, not started
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 4089431, ACTIVE 0 sec dropping table
 
0 lock struct(s), heap size 1160, 0 row lock(s)
 
MySQL thread id 32, OS thread handle 140046885218048, query id 11920 localhost 127.0.0.1 rqg Closing tables
 
DROP DATABASE IF EXISTS testdb_N /* QNO 1278 CON_ID 19 */
 
---TRANSACTION 4089433, ACTIVE 0 sec
 
1 lock struct(s), heap size 1160, 0 row lock(s)
 
---TRANSACTION 23634, ACTIVE 409 sec
 
11 lock struct(s), heap size 1160, 36 row lock(s), undo log entries 31
 
MySQL thread id 33, OS thread handle 140046884914944, query id 12000 localhost 127.0.0.1 rqg Opening tables
 
SHOW CREATE TABLE t6 /* QNO 2170 CON_ID 17 */
 
Trx read view will not see trx with id >= 23630, sees < 23371
 
--------
 
FILE I/O
 
--------
 
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
 
I/O thread 1 state: waiting for completed aio requests (log thread)
 
I/O thread 2 state: waiting for completed aio requests (read thread)
 
I/O thread 3 state: waiting for completed aio requests (read thread)
 
I/O thread 4 state: waiting for completed aio requests (read thread)
 
I/O thread 5 state: waiting for completed aio requests (read thread)
 
I/O thread 6 state: waiting for completed aio requests (write thread)
 
I/O thread 7 state: waiting for completed aio requests (write thread)
 
I/O thread 8 state: waiting for completed aio requests (write thread)
 
I/O thread 9 state: waiting for completed aio requests (write thread)
 
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 
 ibuf aio reads:, log i/o's:, sync i/o's:
 
Pending flushes (fsync) log: 0; buffer pool: 0
 
209 OS file reads, 4473 OS file writes, 1754 OS fsyncs
 
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
 
-------------------------------------
 
INSERT BUFFER AND ADAPTIVE HASH INDEX
 
-------------------------------------
 
Ibuf: size 1, free list len 0, seg size 2, 0 merges
 
merged operations:
 
 insert 0, delete mark 0, delete 0
 
discarded operations:
 
 insert 0, delete mark 0, delete 0
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 0 buffer(s)
 
Hash table size 34679, node heap has 1 buffer(s)
 
Hash table size 34679, node heap has 1 buffer(s)
 
15745.32 hash searches/s, 0.00 non-hash searches/s
 
---
 
LOG
 
---
 
Log sequence number 2926363
 
Log flushed up to   2926284
 
Pages flushed up to 2922665
 
Last checkpoint at  2914385
 
0 pending log flushes, 0 pending chkp writes
 
1240 log i/o's done, 0.00 log i/o's/second
 
----------------------
 
BUFFER POOL AND MEMORY
 
----------------------
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2018-02-19  2:30:27 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 272.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
2018-02-19  2:30:27 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 248.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
2018-02-19  2:30:27 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 272.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 272.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
--Thread 140046210385664 has waited at dict0dict.cc line 7195 for 13.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884914944 has waited at dict0dict.cc line 1162 for 184.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046537799424 has waited at dict0dict.cc line 1162 for 217.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 248.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538102528 has waited at dict0dict.cc line 498 for 187.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 272.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2018-02-19  2:30:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 303.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
2018-02-19  2:30:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046537799424 has waited at dict0dict.cc line 1162 for 248.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
2018-02-19  2:30:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 279.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
2018-02-19  2:30:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 303.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538405632 has waited at ha_innodb.cc line 13024 for 303.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5580c8f59680 created in file dict0dict.cc line 1109
 
a writer (thread id 140046885218048) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 4191
 
--Thread 140046210385664 has waited at dict0dict.cc line 7195 for 44.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884914944 has waited at dict0dict.cc line 1162 for 215.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046537799424 has waited at dict0dict.cc line 1162 for 248.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046884308736 has waited at dict0dict.cc line 498 for 279.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046538102528 has waited at dict0dict.cc line 498 for 218.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
--Thread 140046124443392 has waited at dict0dict.cc line 1003 for 303.00 seconds the semaphore:
 
Mutex at 0x5580c8f59730, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2331
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
Status information:
 
Current dir: /home/travis/logs/vardir1_1/data/
 
Running threads: 12  Cached threads: 1  Stack size: 299008
 
Key caches:
 
default
 
Buffer_size:     134217728
 
Block_size:           1024
 
Division_limit:        100
 
Age_threshold:         300
 
Partitions:              0
 
blocks used:             8
 
not flushed:             0
 
w_requests:            504
 
writes:                358
 
r_requests:           1178
 
reads:                  68
 
handler status:
 
read_key:         1283
 
read_next:         125
 
read_rnd             0
 
read_first:         45
 
write:            1000
 
delete             150
 
update:            219
 
Table status:
 
Opened tables:       1151
 
Open tables:            0
 
Open files:            29
 
Open streams:           0
 
Alarm status:
 
Active alarms:   0
 
Max used alarms: 0
 
Next alarm time: 0
 
Memory status:
 
Non-mmapped space allocated from system: 35213312
 
Number of free chunks:                   1266
 
Number of fastbin blocks:                58
 
Number of mmapped regions:               11
 
Space in mmapped regions:                312356864
 
Maximum total allocated space:           0
 
Space available in freed fastbin blocks: 3648
 
Total allocated space:                   25454464
 
Total free space:                        9758848
 
Top-most, releasable space:              15600
 
Estimated memory (with thread stack):    351457280
 
Global memory allocated by server:       281263424
 
Memory allocated by threads:             792944
 
Events status:
 
LLA = Last Locked At  LUA = Last Unlocked At
 
WOC = Waiting On Condition  DL = Data Locked
 
Event scheduler status:
 
State      : INITIALIZED
 
Thread id  : 0
 
LLA        : n/a:0
 
LUA        : n/a:0
 
WOC        : NO
 
Workers    : 0
 
Executed   : 0
 
Data locked: NO
 
Event queue status:
 
Element count   : 0
 
Data locked     : NO
 
Attempting lock : NO
 
LLA             : init_queue:140
 
LUA             : init_queue:150
 
WOC             : NO
 
Next activation : never
 
180219  2:33:28 [ERROR] mysqld got signal 11 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.3.5-MariaDB-debug-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=8
 
max_threads=153
 
thread_count=16
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467462 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x49000
 
/home/travis/server/bin/mysqld(my_print_stacktrace+0x40)[0x5580c67e8c4f]
 
mysys/stacktrace.c:269(my_print_stacktrace)[0x5580c60159fb]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f5f38da9330]
 
unix/syscall-template.S:81(__poll)[0x7f5f382a0c9d]
 
sql/mysqld.cc:6674(handle_connections_sockets())[0x5580c5c349b1]
 
sql/mysqld.cc:6147(mysqld_main(int, char**))[0x5580c5c33c77]
 
sql/main.cc:26(main)[0x5580c5c28165]
 
csu/libc-start.c:321(__libc_start_main)[0x7f5f381d1f45]
 
/home/travis/server/bin/mysqld(+0x57e059)[0x5580c5c28059]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file at /home/travis/logs/vardir1_1/data/
 
Segmentation fault (core dumped)

experimental 6b97ede2ef98c5ef90c2387528266f7fcde1685d

 
perl /home/travis/rqg/runall-new.pl --duration=350 --threads=6 --seed=1519006890 --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --transformers=ExecuteAsCTE,ExecuteAsDeleteReturning,ExecuteAsExcept,ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsIntersect,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,ExecuteAsPreparedTwice,ExecuteAsSPTwice --redefine=conf/mariadb/general-workarounds.yy --mysqld=--log_output=FILE --views --vcols --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/sequences.yy --redefine=conf/mariadb/xa.yy --basedir=/home/travis/server --mysqld=--log_bin_trust_function_creators=1 --mysqld=--log-bin --mysqld=--max-statement-time=30 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/runtime/WL5004_sql.yy --gendata=conf/runtime/WL5004_data.zz --vardir=/home/travis/logs/vardir1_1

Not reproducible so far.

 Comments   
Comment by Marko Mäkelä [ 2018-04-07 ]

In threads, the master thread (Thread 25) is blocked while waiting for dict_sys->mutex:

#7 0x00005580c652c4c6 in dict_table_open_on_id (table_id=95, dict_locked=0, table_op=DICT_TABLE_OP_OPEN_ONLY_IF_CACHED) at /home/travis/src/storage/innobase/dict/dict0dict.cc:1003
#8 0x00005580c63a4023 in row_drop_tables_for_mysql_in_background () at /home/travis/src/storage/innobase/row/row0mysql.cc:2823
#9 0x00005580c641441a in srv_master_do_active_tasks () at /home/travis/src/storage/innobase/srv/srv0srv.cc:2178
#10 0x00005580c64150fd in srv_master_thread (arg=0x0) at /home/travis/src/storage/innobase/srv/srv0srv.cc:2413

Thread 28 (executing FLUSH TABLES is likewise blocked, waiting for dict_sys->mutex:

#7 0x00005580c652b0c5 in dict_table_close (table=0x7f5ed80ab418, dict_locked=0, try_drop=1) at /home/travis/src/storage/innobase/dict/dict0dict.cc:498
#8 0x00005580c639f623 in row_prebuilt_free (prebuilt=0x7f5ee00d4938, dict_locked=0) at /home/travis/src/storage/innobase/row/row0mysql.cc:1036
#9 0x00005580c624358a in ha_innobase::close (this=0x7f5ee00d3878) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:6682
#10 0x00005580c601cea2 in handler::ha_close (this=0x7f5ee00d3878) at /home/travis/src/sql/handler.cc:2747
#11 0x00005580c5e3a278 in closefrm (table=0x7f5ee00d2c30) at /home/travis/src/sql/table.cc:3595
#12 0x00005580c5f50495 in intern_close_table (table=0x7f5ee00d2c30) at /home/travis/src/sql/table_cache.cc:222
#13 0x00005580c5f508af in tc_purge (mark_flushed=true) at /home/travis/src/sql/table_cache.cc:335
#14 0x00005580c5c9f921 in close_cached_tables (thd=0x7f5ef800b290, tables=0x0, wait_for_refresh=true, timeout=86400) at /home/travis/src/sql/sql_base.cc:377
#15 0x00005580c5ec6c1f in reload_acl_and_cache (thd=0x7f5ef800b290, options=4, tables=0x0, write_to_binlog=0x7f5f2027b780) at /home/travis/src/sql/sql_reload.cc:334
#16 0x00005580c5d2e3bd in mysql_execute_command (thd=0x7f5ef800b290) at /home/travis/src/sql/sql_parse.cc:5599
#17 0x00005580c5d353d0 in mysql_parse (thd=0x7f5ef800b290, rawbuf=0x7f5ef801fa98 "FLUSH TABLES /* QNO 1590 CON_ID 20 */", length=37, parser_state=0x7f5f2027c5f0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7980
#18 0x00005580c5d22bc6 in dispatch_command (command=COM_QUERY, thd=0x7f5ef800b290, packet=0x7f5ef80156d1 "FLUSH TABLES /* QNO 1590 CON_ID 20 */ ", packet_length=38, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1825

Likewise waiting for dict_sys->mutex are Thread 30 (opening a table for SELECT) and 35 (opening for SHOW CREATE TABLE).
Thread 37 is waiting for dict_sys->mutex when closing a table handle in LOAD DATA INFILE:

#6 0x00005580c62673de in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x5580c8f59730, n_spins=30, n_delay=4, name=0x5580c6b4de68 "/home/travis/src/storage/innobase/dict/dict0dict.cc", line=498) at /home/travis/src/storage/innobase/include/ib0mutex.h:635
#7 0x00005580c652b0c5 in dict_table_close (table=0x7f5ef806a358, dict_locked=0, try_drop=1) at /home/travis/src/storage/innobase/dict/dict0dict.cc:498
#8 0x00005580c639f623 in row_prebuilt_free (prebuilt=0x7f5ef81312d8, dict_locked=0) at /home/travis/src/storage/innobase/row/row0mysql.cc:1036
#9 0x00005580c624358a in ha_innobase::close (this=0x7f5ef80d3f38) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:6682
#10 0x00005580c601cea2 in handler::ha_close (this=0x7f5ef80d3f38) at /home/travis/src/sql/handler.cc:2747
#11 0x00005580c5e3a278 in closefrm (table=0x7f5ef80bce50) at /home/travis/src/sql/table.cc:3595
#12 0x00005580c5f50495 in intern_close_table (table=0x7f5ef80bce50) at /home/travis/src/sql/table_cache.cc:222
#13 0x00005580c5f50634 in tc_remove_table (table=0x7f5ef80bce50) at /home/travis/src/sql/table_cache.cc:260
#14 0x00005580c5f50fa1 in tc_release_table (table=0x7f5ef80bce50) at /home/travis/src/sql/table_cache.cc:472
#15 0x00005580c5ca0c0f in close_thread_table (thd=0x7f5ee800b460, table_ptr=0x7f5ee800b550) at /home/travis/src/sql/sql_base.cc:909
#16 0x00005580c5ca08e0 in close_thread_tables (thd=0x7f5ee800b460) at /home/travis/src/sql/sql_base.cc:851
#17 0x00005580c5d30b72 in mysql_execute_command (thd=0x7f5ee800b460) at /home/travis/src/sql/sql_parse.cc:6329
#18 0x00005580c5d353d0 in mysql_parse (thd=0x7f5ee800b460, rawbuf=0x7f5ee80203b8 "LOAD DATA INFILE 'load_table10_int' REPLACE INTO TABLE table10_int /* QNO 1917 CON_ID 15 */", length=91, parser_state=0x7f5f34ca75f0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7980

Thread 38 (executing CREATE TABLE) is waiting for dict_operation_lock already, not yet holding dict_sys->mutex:

#6 0x00005580c6399492 in pfs_rw_lock_x_lock_func (lock=0x5580c8f59680, pass=0, file_name=0x5580c6a4b660 "/home/travis/src/storage/innobase/handler/ha_innodb.cc", line=13024) at /home/travis/src/storage/innobase/include/sync0rw.ic:568
#7 0x00005580c63a2c75 in row_mysql_lock_data_dictionary_func (trx=0x7f5f34e67e08, file=0x5580c6a4b660 "/home/travis/src/storage/innobase/handler/ha_innodb.cc", line=13024) at /home/travis/src/storage/innobase/row/row0mysql.cc:2328

The hog seems to be Thread 39, executing DROP DATABASE:

#0 0x00005580c646642e in trx_start_low (trx=0x7f5f34e674d8, read_write=true) at /home/travis/src/storage/innobase/trx/trx0trx.cc:1166
#1 0x00005580c646a36d in trx_start_internal_low (trx=0x7f5f34e674d8) at /home/travis/src/storage/innobase/trx/trx0trx.cc:2555
#2 0x00005580c646a406 in trx_start_for_ddl_low (trx=0x7f5f34e674d8, op=TRX_DICT_OP_TABLE) at /home/travis/src/storage/innobase/trx/trx0trx.cc:2597
#3 0x00005580c63a5e1d in row_drop_table_for_mysql (name=0x7f5ed82dbc50 "testdb_N/#sql-ib95-3920410403", trx=0x7f5f34e674d8, drop_db=true, create_failed=0, nonatomic=true) at /home/travis/src/storage/innobase/row/row0mysql.cc:3607
#4 0x00005580c63a7824 in row_drop_database_for_mysql (name=0x7f5ed8078300 "testdb_N/", trx=0x7f5f34e674d8, found=0x7f5f34d83c60) at /home/travis/src/storage/innobase/row/row0mysql.cc:4278
#5 0x00005580c6252b85 in innobase_drop_database (hton=0x5580c81f4080, path=0x7f5f34d841c0 "./testdb_N/") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:13489
#6 0x00005580c6018300 in dropdb_handlerton (unused1=0x0, plugin=0x7f5ed8274b40, path=0x7f5f34d841c0) at /home/travis/src/sql/handler.cc:712

Thread 39 is holding both dict_sys->mutex and dict_operation_lock. What is it waiting for?

		/* Temporary rseg is assigned only if the transaction
 
		updates a temporary table */
 
		trx->rsegs.m_redo.rseg = trx_assign_rseg_low();
 
		ut_ad(trx->rsegs.m_redo.rseg != 0
 
		      || srv_read_only_mode
 
		      || srv_force_recovery >= SRV_FORCE_NO_TRX_UNDO);
 
 
 
		trx_sys.register_rw(trx);

Line 1166 in commit afc56a509cc7d3d651ca68ad826ca183da8dc7cc is the assertion above. It should not block. Could it instead be somehow looping in trx_assign_rseg_low() or trx_sys.register_rw()? Commit 6b97ede2ef98c5ef90c2387528266f7fcde1685d does not exist anymore. If threads was actually for that commit, I would like to know which exact statement was in line 1166. Based on the issue filing date and the commit history, line 1166 should be as described above. The file was changed on February 15 and 20, and the issue was filed on February 19.

It might be worth noting (but maybe not the reason of this hang) that the DROP DATABASE is dropping a #sql-ib table that must have been created by a table-rebuilding ALTER TABLE operation that was executed with ALGORITHM=INPLACE (not ALGORITHM=COPY).

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