MySQL Bugs: #106412: The server was crashed because of long semaphore wait

Bug #106412	The server was crashed because of long semaphore wait
Submitted:	9 Feb 2022 3:24	Modified:	9 Feb 2022 13:35
Reporter:	Huaisong Hui (OCA)	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Storage Engine API	Severity:	S3 (Non-critical)
Version:	5.7.20	OS:	CentOS
Assigned to:		CPU Architecture:	x86

Description:
A mysql instance was crashed because of long semaphore wait and all threads were pending.
The workload was very low.

Quoted from error file:

2022-02-08T15:25:05.925607Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140588648670976 has waited at btr0sea.cc line 1300 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x3ba3a78 created in file btr0sea.cc line 195
a writer (thread id 140588648670976) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 1204
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/btr/btr0sea.cc line 1300
2022-02-08T15:25:05.925751Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140587770349312 has waited at btr0sea.ic line 90 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x3ba3378 created in file btr0sea.cc line 195
a writer (thread id 140587770349312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/include/btr0sea.ic line 90
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2022-02-08 23:25:09 0x7fdd56d41700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 14 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2575204 srv_active, 0 srv_shutdown, 806619 srv_idle
srv_master_thread log flush and writes: 3381539
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 489883236
--Thread 140588648670976 has waited at btr0sea.cc line 1300 for 245.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x3ba3a78 created in file btr0sea.cc line 195
a writer (thread id 140588648670976) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 1204
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/btr/btr0sea.cc line 1300
--Thread 140584880903936 has waited at btr0sea.cc line 1204 for 128.00 seconds the semaphore:
S-lock on RW-latch at 0x3ba3378 created in file btr0sea.cc line 195
a writer (thread id 140587770349312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/include/btr0sea.ic line 90
--Thread 140588575848192 has waited at btr0sea.cc line 1204 for 145.00 seconds the semaphore:
S-lock on RW-latch at 0x3ba3378 created in file btr0sea.cc line 195
a writer (thread id 140587770349312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff

……

Last time read locked in file btr0sea.ic line 128
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/include/btr0sea.ic line 90
--Thread 140587769808640 has waited at btr0sea.cc line 1204 for 144.00 seconds the semaphore:
S-lock on RW-latch at 0x3ba3378 created in file btr0sea.cc line 195
a writer (thread id 140587770349312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file /export/home/pb2/build/sb_0-24964902-1505322433.76/mysqlcom-pro-5.7.20/storage/innobase/include/btr0sea.ic line 90
OS WAIT ARRAY INFO: signal count 407053019
RW-shared spins 0, rounds 831748477, OS waits 260315298
RW-excl spins 0, rounds 6087236654, OS waits 166941876
RW-sx spins 4452713, rounds 90761781, OS waits 1737849
Spin rounds per wait: 831748477.00 RW-shared, 6087236654.00 RW-excl, 20.38 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-02-08 18:31:30 0x7fdc77eb5700
*** (1) TRANSACTION:
TRANSACTION 1152556612, ACTIVE 38 sec starting index read
mysql tables in use 2, locked 2
LOCK WAIT 77 lock struct(s), heap size 8400, 8165 row lock(s), undo log entries 66
MySQL thread id 686457, OS thread handle 140584860088064, query id 21645822324 172.16.0.246 lfy Sending data
update j_freight j,j_freight_error_his t set j.freightStatus='0' where t.file_download=120591 and t.error_status = '3' and j.start_time!=t.start_date and j.end_time!=t.end_date and j.start_port=t.startport_code and j.dest_port_name = t.endport_name and j.transferport_name=t.hubport_name and j.carrier_code=t.carrier_code and j.carrier_sealine=t.carrier_sealine and j.searoute_code=t.sealine_code
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 18781 page no 4503 n bits 304 index only_one of table `lfy`.`j_freight` trx id 1152556612 lock_mode X locks rec but not gap waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 3; hex 494e44; asc IND;;
 1: len 5; hex 434e4e424f; asc CNNBO;;
 2: len 8; hex 43616c6375747461; asc Calcutta;;
 3: len 9; hex 53696e6761706f7265; asc Singapore;;
 4: len 3; hex 4f4e45; asc ONE;;
 5: len 3; hex 505333; asc PS3;;
 6: len 8; hex 8000000000036f1d; asc       o ;;

*** (2) TRANSACTION:
TRANSACTION 422063890349728, ACTIVE 90 sec fetching rows, thread declared inside InnoDB 4096
mysql tables in use 24, locked 24
18841 lock struct(s), heap size 1827024, 1152967 row lock(s)
MySQL thread id 686449, OS thread handle 140584881444608, query id 21641517980 event_scheduler
INSERT INTO temp_gen_freight_wait2 SELECT *,NOW() FROM view_gen_freight
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 18781 page no 4503 n bits 304 index only_one of table `lfy`.`j_freight` trx id 422063890349728 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 3; hex 494e44; asc IND;;
 1: len 5; hex 434e4e424f; asc CNNBO;;
 2: len 8; hex 43616c6375747461; asc Calcutta;;
 3: len 9; hex 53696e6761706f7265; asc Singapore;;
 4: len 6; hex 434f53434f4e; asc COSCON;;
 5: len 3; hex 464345; asc FCE;;
 6: len 8; hex 800000000002ece4; asc         ;;

……

How to repeat:
I don't know

Suggested fix:
I don't know

error log

Attachment: error.log (application/octet-stream, text), 92.07 KiB.

Hi Mr. Hui,

Thank you for your bug report.

However, this is not a bug.

Simply, deadlocks and long lock waits (sometimes called semaphore waits) are a normal phenomena in storage engines that abide by the pessimistic ACID standards, like InnoDB and vast majority of other transactional storage engine. 

Hence, these conditions are considered as expected behaviour.

The problem can arise due to the badly designed schema , slow front end, normalisation that is not attempted beyond second level, suboptimal index creation, not well written queries and many other factors.

However, in most cases, we have discovered that long semaphore waits are mostly caused by the transaction waiting for some unrelated processing , but even more often, this is due to badly designed application that waits for the end user's input while transaction has been started.

Not a bug.