[MDEV-21253] 10.1.43 crash Created: 2019-12-09  Updated: 2020-01-12  Resolved: 2020-01-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1, 10.1.43
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Yam Assignee: Marko Mäkelä
Resolution: Incomplete Votes: 0
Labels: need_feedback

Issue Links:
Relates
relates to MDEV-20243 semaphore hang and crash in 10.3.16 w... Closed
relates to MDEV-20414 "a long semaphore wait" After Upgradi... Open

 Description   

MariaDB has stopped responding.
The process was forcibly killed and started.
I used it as a replication server.

Post part of the error log.
Do you understand the cause?

191209 15:08:57 [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.1.43-MariaDB
 
key_buffer_size=1073741824
 
read_buffer_size=4194304
 
max_used_connections=801
 
max_threads=802
 
thread_count=90
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 7635199 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f2bbe3da008
 
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 = 0x7f2ba468cd40 thread_stack 0x49000
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 241.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 241.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 240.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 240.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 240.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 239.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 233.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 224.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 223.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
 
 
=====================================
 
2019-12-09 15:13:16 7f2be17ff700 INNODB MONITOR OUTPUT
 
=====================================
 
Per second averages calculated from the last 66 seconds
 
-----------------
 
BACKGROUND THREAD
 
-----------------
 
srv_master_thread loops: 2184056 srv_active, 0 srv_shutdown, 117 srv_idle
 
srv_master_thread log flush and writes: 2184172
 
----------
 
SEMAPHORES
 
----------
 
OS WAIT ARRAY INFO: reservation count 72135263
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 251.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 250.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 250.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 250.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 249.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 243.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 234.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 233.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
OS WAIT ARRAY INFO: signal count 11407127770
 
Mutex spin waits 5353292603, rounds 4633262882, OS waits 10999248
 
RW-shared spins 6691088911, rounds 11585815825, OS waits 17090184
 
RW-excl spins 1402674973, rounds 19062627835, OS waits 30948801
 
Spin rounds per wait: 0.87 mutex, 1.73 RW-shared, 13.59 RW-excl
 
------------
 
TRANSACTIONS
 
------------
 
Trx id counter 135606152205
 
Purge done for trx's n:o < 135606150760 undo n:o < 0 state: running but idle
 
History list length 57
 
LIST OF TRANSACTIONS FOR EACH SESSION:
 
---TRANSACTION 0, not started
 
MySQL thread id 168156173, OS thread handle 0x7f2b76e8d700, query id 8434021673 172.16.38.11 dbadmin Opening tables
 
SELECT RD.rank,
 
                           L.lady_num,
 
                           L.name,
 
                           L.age,
 
                           L.height,
 
                           L.bust,
 
                           L.cup,
 
                           L.waist,
 
                           L.hip,
 
                           L.new_flg,
 
                           L.up_flg,
 
                           L.imagename,
 
                           L.thumbname
 
                      FROM ranking_data AS RD
 
                     INNER JOIN lady AS L ON RD.lady_num = L.lady_num AND L.open = 1
 
 
 
---TRANSACTION 0, not started
 
MySQL thread id 168155974, OS thread handle 0x7f2ba45f9700, query id 8434021659 172.16.38.11 dbadmin Opening tables
 
SELECT COUNT(L.lady_num)
 
                  FROM schedule_realtime AS SR
 
                 INNER JOIN lady AS L ON SR.lady_num = L.lady_num
 
                 WHERE L.shop_num = '494' AND L.open = 1
 
---TRANSACTION 0, not started
 
MySQL thread id 168155691, OS thread handle 0x7f2b5cf4d700, query id 8434021646 172.16.38.11 dbadmin Opening tables
 
SELECT COUNT(L.lady_num)
 
                  FROM lady AS L
 
                 WHERE L.shop_num = '70' AND L.open = 1
 
---TRANSACTION 0, not started
 
MySQL thread id 168156118, OS thread handle 0x7f2b8e5af700, query id 8434021626 172.16.38.11 dbadmin Opening tables
 
SELECT R.pc_path,
 
                   R.sp_path,
 
                   R.mb_path
 
              FROM redirect AS R
 
             INNER JOIN shop AS S ON R.shop_num = S.shop_num
 
             WHERE R.old_path = '/css/sp/custom_sp_d.css'
 
               AND S.open IN (1, 2)
 
               AND S.domain = 's-taurus.com'
 
             ORDER BY R.narabi
 
---TRANSACTION 135606152162, not started
 
MySQL thread id 168156218, OS thread handle 0x7f2b4510f700, query id 8434021609 172.16.38.11 undernavi Opening tables
 
SELECT COUNT(L.lady_num)
 
                  FROM lady AS L
 
                  INNER JOIN schedule_week AS SC ON L.lady_num = SC.lady_num AND SC.date = '2019-12-09'
 
                 WHERE L.open = 1 AND L.shop_num = '8441' AND SC.work_flg = 1
 
---TRANSACTION 135606152193, not started
 
MySQL thread id 168156206, OS thread handle 0x7f2b4836b700, query id 8434021617 172.16.38.11 dbadmin Opening tables
 
SELECT COUNT(BC.blog_comment_id)
 
                      FROM blog_comment AS BC
 
                     WHERE BC.blog_id = '894092' AND BC.open = 1
 
---TRANSACTION 135606152138, not started sleeping before entering InnoDB
 
mysql tables in use 6, locked 0
 
MySQL thread id 168156192, OS thread handle 0x7f2b98997700, query id 8434021445 172.16.38.11 undernavi Copying to tmp table
 
SELECT T.top_banner_id,
 
                       T.shop_num,
 
                       T.title,
 
                       T.comment,
 
                       T.pc_url,
 
                       T.image_name160x60,
 
                       T.image_name200x40,
 
                       T.image_name288x288,
 
                       T.image_name180x60,
 
                       T.target,
 
                       S.name,
 
                       C.name AS category_name,
 
                       AM.name_e AS tiku_name_e,
 
                       AP.name_e AS pref_name_e,
 
                       AP.name AS pref_name,
 
              
---TRANSACTION 135606152201, not started
 
MySQL thread id 168156156, OS thread handle 0x7f326f44d700, query id 8434021588 172.16.38.11 dbadmin Opening tables
 
SELECT L.*
 
                  FROM lady AS L
 
                 WHERE L.lady_num = '57344'
 
                   AND L.shop_num = '772'
 
                   AND L.open = 1
 
---TRANSACTION 135606152168, not started
 
MySQL thread id 168156147, OS thread handle 0x7f2b97f5f700, query id 8434021517 172.16.38.11 undernavi Opening tables
 
SELECT COUNT(V.voice_id)
 
                  FROM voice AS V
 
                 INNER JOIN lady AS L ON V.lady_num = L.num AND L.open = 1
 
                 WHERE L.shop_num = '10427' AND V.open = 1 AND V.lady_num = '952044'
 
---TRANSACTION 135606152195, not started
 
MySQL thread id 168156124, OS thread handle 0x7f2b2bc87700, query id 8434021574 172.16.38.11 undernavi Opening tables
 
SELECT url, imagename, title FROM official_banner WHERE 1 AND tiku_num = 1 AND door_flg = 1 ORDER BY RAND('1575871730') LIMIT 0, 1
 
---TRANSACTION 135606150479, not started sleeping before entering InnoDB
 
mysql tables in use 9, locked 0
 
MySQL thread id 168156046, OS thread handle 0x7f2b9c4d1700, query id 8434021131 172.16.38.11 undernavi Copying to tmp table
 
SELECT M.premium_movie_id,
 
                           M.file_id,
 
                           M.domain,
 
                           M.title,
 
                           M.comment,
 
                           M.open_date,
 
                           M.type,
 
                           M.number,
 
                           S.num AS shop_num,
 
                           S.name AS shop_name,
 
                           S.tel1,
 
                           S.tel2,
 
                           S.tel3,
 
                           S.tel_flg,
 
                           S.shop_hour_start,
 
                           S.
 
---TRANSACTION 135606151766, not started
 
MySQL thread id 5, OS thread handle 0x7f2bd3436700, query id 8434020616 Waiting for work from SQL thread
 
---TRANSACTION 135606151756, not started
 
MySQL thread id 4, OS thread handle 0x7f2bd3480700, query id 8434020612 Waiting for work from SQL thread
 
---TRANSACTION 135606151761, not started
 
MySQL thread id 6, OS thread handle 0x7f2bd33ec700, query id 8434020610 Waiting for work from SQL thread
 
---TRANSACTION 135606151765, not started
 
MySQL thread id 8, OS thread handle 0x7f2bd3358700, query id 8434020630 Waiting for work from SQL thread
 
---TRANSACTION 135606151759, not started
 
MySQL thread id 9, OS thread handle 0x7f2bd330e700, query id 8434020622 Waiting for work from SQL thread
 
---TRANSACTION 135606151545, not started
 
MySQL thread id 7, OS thread handle 0x7f2bd33a2700, query id 8434020180 Waiting for work from SQL thread
 
---TRANSACTION 135606151757, not started
 
MySQL thread id 10, OS thread handle 0x7f2bd32c4700, query id 8434020615 Waiting for work from SQL thread
 
---TRANSACTION 135606151548, not started
 
MySQL thread id 11, OS thread handle 0x7f2bd327a700, query id 8434020175 Waiting for work from SQL thread
 
---TRANSACTION 135606151762, not started
 
MySQL thread id 12, OS thread handle 0x7f2bd3230700, query id 8434021575 apply log event
 
---TRANSACTION 135606151767, not started
 
MySQL thread id 13, OS thread handle 0x7f2bd31e6700, query id 8434020621 Waiting for work from SQL thread
 
---TRANSACTION 132229461507, not started
 
MySQL thread id 1, OS thread handle 0x7f2bd35f2700, query id 0 Waiting for background binlog tasks
 
---TRANSACTION 135606152203, ACTIVE 259 sec
 
Trx read view will not see trx with id >= 135606152204, sees < 135606152204
 
Trx #rec lock waits 0 #table lock waits 0
 
Trx total rec lock wait time 0 SEC
 
Trx total table lock wait time 0 SEC
 
--------
 
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, 0] , aio writes: 0 [0, 0, 0, 0] ,
 
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
 
Pending flushes (fsync) log: 0; buffer pool: 0
 
907601 OS file reads, 135589812 OS file writes, 103743823 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 1344, seg size 1346, 3250 merges
 
merged operations:
 
 insert 22634, delete mark 4579, delete 534
 
discarded operations:
 
 insert 0, delete mark 0, delete 0
 
0.00 hash searches/s, 0.00 non-hash searches/s
 
---
 
LOG
 
---
 
Log sequence number 22028988024175
 
Log flushed up to   22028988024175
 
Pages flushed up to 22028988024175
 
Last checkpoint at  22028854710423
 
Max checkpoint age    433446544
 
Checkpoint age target 419901340
 
Modified age          0
 
Checkpoint age        133313752
 
0 pending log writes, 0 pending chkp writes
 
92353570 log i/o's done, 0.00 log i/o's/second
 
----------------------
 
BUFFER POOL AND MEMORY
 
----------------------
 
Total memory allocated 26990346240; in additional pool allocated 0
 
Total memory allocated by read views 12304
 
Internal hash tables (constant factor + variable factor)
 
    Adaptive hash index 757940160 	(407990104 + 349950056)
 
    Page hash           1107208 (buffer pool 0 only)
 
    Dictionary cache    103685016 	(101999056 + 1685960)
 
    File system         3922936 	(812272 + 3110664)
 
    Lock system         63781112 	(63750152 + 30960)
 
    Recovery system     0 	(0 + 0)
 
Dictionary memory allocated 1685960
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 272.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 270.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 264.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 255.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 254.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 272.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 271.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 270.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 264.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 255.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 254.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
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
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 303.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 301.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 295.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 286.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 285.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139826279982848 has waited at dict0stats_bg.cc line 418 for 303.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824219870976 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825418049280 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139824655292160 has waited at dict0dict.cc line 1138 for 302.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825471084288 has waited at dict0dict.cc line 1138 for 301.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825907078912 has waited at dict0dict.cc line 1138 for 295.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825276352256 has waited at dict0dict.cc line 1138 for 286.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 139825292523264 has waited at dict0dict.cc line 1138 for 285.00 seconds the semaphore:
 
Mutex at 0x7f32c7013d68 '&dict_sys->mutex', lock var 1
 
Last time reserved by thread 139826290472704 in file not yet reserved line 0, waiters flag 1
 
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
 
 



 Comments   
Comment by Marko Mäkelä [ 2019-12-09 ]

y-yamamoto, your report seems very similar to MDEV-20243 and MDEV-20414.

Based on the output that you provided so far, we only know that InnoDB has observed that a thread is likely stuck while holding dict_sys->mutex, but we do not know the root cause.

Are you using InnoDB fulltext indexes or persistent statistics? I wonder if the hang could be related to those.

Could you please attach gdb to the mysqld process while it is hung, and provide a stack of all threads, and also information about the dictionary latches? You should try to install a debug symbol package first.

gdb -ex "set pagination 0" -ex "thread apply all bt" -ex "print *dict_operation_lock" -ex "print *dict_sys->mutex" --batch -p $(pgrep -x mysqld)

We want to be able to detect the chain of blocked mutexes or rw-latches and threads.

Comment by Yam [ 2019-12-10 ]

Since I don't know how to reproduce it, I can't debug it.
Please close once.
If it happens again, we will consult again.

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