MySQL Bugs: #80919: MySQL Crashes when Droping Indexes

Bug #80919	MySQL Crashes when Droping Indexes - Long semaphore wait
Submitted:	31 Mar 2016 6:23	Modified:	23 Jan 2019 13:45
Reporter:	Ramiro Cavalcanti	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.7.18	OS:	Oracle Linux (6)
Assigned to:		CPU Architecture:	Any

Description:
Hi,
my mysql was compiled (its not from the distro).

I have about 280 databases at a dedicated mysql-server with 30Gb RAM, innodb_buffer_pool is set to 20Gb.

When i use a script to "patch" all my costumers databases (all 280), everytime that i try to DROP some unused columns, mysql crashes and dont start again.

I have this same behavior 3 times. When this happan, i restore all databases without any problem from individual.sql dumps that i have.

It stops when i do some of these lines (this is a part of my patch.sql):

-- venda item
ALTER TABLE `venda_item` DROP INDEX `thread_produto`;
ALTER TABLE `venda_item` DROP `thread_produto`;
ALTER TABLE `forma_pg` DROP INDEX `thread_superpay_lib_cartao`;
ALTER TABLE `forma_pg` DROP `thread_superpay_lib_cartao`;
ALTER TABLE `forma_pg` DROP INDEX `thread_superpay_lib_cartao`;
ALTER TABLE `forma_pg` DROP `thread_finan_custo`;
ALTER TABLE `forma_pg` DROP `thread_finan_class`;
ALTER TABLE `forma_pg` DROP `thread_braspag_paymentmethod`;

My guess is that if i do not DROP INDEX first, and try to drop the column, it crashes (like i do with thread_finan_custo, thread_finan_class and thread_braspag_paymentmethod), it makes mysql crash.
 
I didn't tried to remove INDEX before i try to DROP the column. I will try this tomorrow to confirm.

Also, ive changed my Hard Drive to another one, and my server (Dell R620 with 64Gb RAM dont show any problem at iDrac/HardDrives).

In fact, im facing this problems since i upgraded from version 5.6.29 to 5.7.11 30 days ago.

Im using version 5.6.29 for about 3 years with the same databases and server without any problem.

How to repeat:
Heres part of the log, i dont know where i can upload it all:

2016-03-29T07:56:14.194195Z 5 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-03-29T07:56:14.194719Z 5 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-03-30T03:52:29.053922Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139677377189632 has waited at dict0load.cc line 3761 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f0c7dff9ea0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/include/mtr0mtr.ic line 117
2016-03-30T03:52:29.054063Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139677436737280 has waited at btr0cur.cc line 1870 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f0c7dff9ea0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/include/mtr0mtr.ic line 117
2016-03-30T03:52:29.054099Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139677428344576 has waited at row0row.cc line 1073 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f0ae3bf01a0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: ffffffffdfffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/btr/btr0cur.cc line 1870
2016-03-30T03:52:29.054128Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139677504734976 has waited at fsp0fsp.cc line 3323 for 241.00 seconds the semaphore:
X-lock on RW-latch at 0x2c458ab8 created in file fil0fil.cc line 1353
a writer (thread id 139677436737280) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/fsp/fsp0fsp.cc line 3323
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2016-03-30 00:52:41 0x7f0936221700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 63673 srv_active, 0 srv_shutdown, 7721 srv_idle
srv_master_thread log flush and writes: 71391
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 159060
--Thread 139677377189632 has waited at dict0load.cc line 3761 for 253.00 seconds the semaphore:
S-lock on RW-latch at 0x7f0c7dff9ea0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/include/mtr0mtr.ic line 117
--Thread 139677436737280 has waited at btr0cur.cc line 1870 for 253.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f0c7dff9ea0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/include/mtr0mtr.ic line 117
--Thread 139677428344576 has waited at row0row.cc line 1073 for 253.00 seconds the semaphore:
S-lock on RW-latch at 0x7f0ae3bf01a0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: ffffffffdfffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/btr/btr0cur.cc line 1870
--Thread 139677505001216 has waited at dict0dict.cc line 1239 for 246.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139676757255936 has waited at buf0flu.cc line 1209 for 251.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f0c7dff9ea0 created in file buf0buf.cc line 1417
a writer (thread id 139677436737280) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/include/mtr0mtr.ic line 117
--Thread 139677531244288 has waited at srv0srv.cc line 1959 for 252.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x2c487318 created in file dict0dict.cc line 1184
a writer (thread id 139677531244288) has reserved it in mode  wait exclusive
number of readers 2, waiters flag 0, lock_word: fffffffffffffffe
Last time read locked in file row0upd.cc line 151
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/row/row0mysql.cc line 4261
--Thread 139677504734976 has waited at fsp0fsp.cc line 3323 for 253.00 seconds the semaphore:
X-lock on RW-latch at 0x2c458ab8 created in file fil0fil.cc line 1353
a writer (thread id 139677436737280) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /root/download/mysql-5.7.11/storage/innobase/fsp/fsp0fsp.cc line 3323
--Thread 139677375059712 has waited at dict0dict.cc line 1239 for 244.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677411559168 has waited at dict0stats_bg.cc line 309 for 244.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677377988352 has waited at dict0dict.cc line 1239 for 243.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677375858432 has waited at dict0dict.cc line 1239 for 243.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677376390912 has waited at dict0dict.cc line 1239 for 237.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677505533696 has waited at dict0dict.cc line 1239 for 232.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677377455872 has waited at dict0dict.cc line 1239 for 228.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677504202496 has waited at dict0dict.cc line 1239 for 221.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677376923392 has waited at dict0dict.cc line 1239 for 220.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677375325952 has waited at dict0dict.cc line 1239 for 214.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677376657152 has waited at dict0dict.cc line 1239 for 210.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677375592192 has waited at dict0dict.cc line 1239 for 209.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677376124672 has waited at dict0dict.cc line 1239 for 205.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677505267456 has waited at dict0dict.cc line 1239 for 182.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677377722112 has waited at dict0dict.cc line 1239 for 180.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677374793472 has waited at dict0dict.cc line 1239 for 177.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677374527232 has waited at dict0dict.cc line 1239 for 165.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677374260992 has waited at dict0dict.cc line 1239 for 145.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677373994752 has waited at dict0dict.cc line 1239 for 136.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677373728512 has waited at dict0dict.cc line 1239 for 133.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677373462272 has waited at dict0dict.cc line 1239 for 130.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677373196032 has waited at dict0dict.cc line 1239 for 129.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677372929792 has waited at dict0dict.cc line 1239 for 123.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677372663552 has waited at dict0dict.cc line 1239 for 118.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677372397312 has waited at dict0dict.cc line 1239 for 101.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677372131072 has waited at dict0dict.cc line 1239 for 85.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677371864832 has waited at dict0dict.cc line 1239 for 74.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677371598592 has waited at dict0dict.cc line 1239 for 68.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677371332352 has waited at dict0dict.cc line 1239 for 65.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677371066112 has waited at dict0dict.cc line 1239 for 60.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677370799872 has waited at dict0dict.cc line 1239 for 34.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677370533632 has waited at dict0dict.cc line 1239 for 33.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677370267392 has waited at dict0dict.cc line 1239 for 31.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677370001152 has waited at dict0dict.cc line 1239 for 29.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677302519552 has waited at dict0dict.cc line 1239 for 21.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677302253312 has waited at dict0dict.cc line 1239 for 13.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

--Thread 139677301987072 has waited at dict0dict.cc line 1239 for 5.00 seconds the semaphore:
Mutex at 0x2c4873b8, Mutex DICT_SYS created dict0dict.cc:1173, lock var 1

OS WAIT ARRAY INFO: signal count 169984
RW-shared spins 0, rounds 216602, OS waits 88194
RW-excl spins 0, rounds 1231345, OS waits 8123
RW-sx spins 13386, rounds 289585, OS waits 4670
Spin rounds per wait: 216602.00 RW-shared, 1231345.00 RW-excl, 21.63 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2016-03-29 17:34:06 0x7f09340d8700 Transaction:
TRANSACTION 2983648, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
8 lock struct(s), heap size 1136, 71 row lock(s), undo log entries 3
MySQL thread id 368389, OS thread handle 139677504734976, query id 16459354 192.168.1.6 aosdb_u710 updating
DELETE FROM os_extra_opcao WHERE 1=1  AND id = 663
Foreign key constraint fails for table `agoraosdb_db710`.`os_extra_resposta`:
,
  CONSTRAINT `os_extra_resposta_ibfk_5` FOREIGN KEY (`thread_os_extra_opcao`) REFERENCES `os_extra_opcao` (`id`)
Trying to delete or update in parent table, in index PRIMARY tuple:
DATA TUPLE: 10 fields;
 0: len 4; hex 80000297; asc     ;;
 1: len 6; hex 0000002d86e0; asc    -  ;;
 2: len 7; hex 2800000de92156; asc (    !V;;
 3: len 4; hex 80000002; asc     ;;
 4: len 11; hex 4a4320436f6e74726f6c73; asc JC Controls;;
 5: len 4; hex 0000001e; asc     ;;
 6: len 1; hex 02; asc  ;;
 7: SQL NULL;
 8: SQL NULL;
 9: SQL NULL;

But in child table `agoraosdb_db710`.`os_extra_resposta`, in index thread_os_extra_opcao, there is a record:
PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80000297; asc     ;;
 1: len 4; hex 800a52c7; asc   R ;;

------------
TRANSACTIONS
------------
Trx id counter 4094319
Purge done for trx's n:o < 4094316 undo n:o < 0 state: running
History list length 788
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 4094318, ACTIVE 253 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 443229, OS thread handle 139677504734976, query id 22230253 192.168.1.6 root updating
UPDATE `lib_forma_pg` SET `id` = 1,`forma` = 'Boleto',`id_lib_cfe_meio_pgto` = NULL,`created_at` = NULL,`updated_at` = NULL,`deleted_at` = NULL WHERE `lib_forma_pg`.`id` = 1
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (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
329 OS file reads, 3157788 OS file writes, 1875162 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 6639851, node heap has 952 buffer(s)
Hash table size 6639851, node heap has 1488 buffer(s)
Hash table size 6639851, node heap has 1128 buffer(s)
Hash table size 6639851, node heap has 1229 buffer(s)
Hash table size 6639851, node heap has 2100 buffer(s)
Hash table size 6639851, node heap has 1177 buffer(s)
Hash table size 6639851, node heap has 1190 buffer(s)
Hash table size 6639851, node heap has 921 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 7330641990
Log flushed up to   7330641990
Pages flushed up to 7321475788
Last checkpoint at  7320763793
0 pending log flushes, 0 pending chkp writes
785131 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 27485798400
Dictionary memory allocated 3648778004
Buffer pool size   1638200
Free buffers       659765
Database pages     968250
Old database pages 357257
Modified db pages  423
Pending reads 0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 520, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 296, created 967954, written 1576794
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 968250, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   204775
Free buffers       84034
Database pages     119483
Old database pages 44086
Modified db pages  102
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 39, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 40, created 119443, written 208233
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 119483, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   204775
Free buffers       82457
Database pages     121061
Old database pages 44668
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 75, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 8, created 121053, written 177019
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 121061, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   204775
Free buffers       65731
Database pages     137776
Old database pages 50838
Modified db pages  7
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 59, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 9, created 137767, written 196823
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 137776, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   204775
Free buffers       68027
Database pages     135467
Old database pages 49986
Modified db pages  11
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 58, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 76, created 135391, written 221366
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 135467, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   204775
Free buffers       86793
Database pages     116700
Old database pages 43058
Modified db pages  26
Pending reads 0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 72, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 105, created 116595, written 179554
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 116700, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   204775
Free buffers       88783
Database pages     114699
Old database pages 42320
Modified db pages  26
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 57, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 32, created 114667, written 172142
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 114699, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   204775
Free buffers       85623
Database pages     117886
Old database pages 43496
Modified db pages  90
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 113, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 10, created 117876, written 232106
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 117886, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   204775
Free buffers       98317
Database pages     105178
Old database pages 38805
Modified db pages  161
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 47, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 16, created 105162, written 189551
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 105178, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
1 tablespace extents now reserved for B-tree split operations
Process ID=26436, Main thread ID=139677531244288, state: enforcing dict cache limit
Number of rows inserted 140849033, updated 28489, deleted 47923, read 1642126472
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Also, the majority of databases are small, under 30Megabyte... only about 10 are between 30 to 200M.

Hi,
i've made a 4th try and same problem.

But, with a smaller "patch.sql" that has a few ALTER TABLES.

I will add the "mysqld.log"
and "patch_4.3.3_00_paulo_nfse_ajustes_e_nova_tabela.sql" that was used.

This is make me crazy. I just cant update my customer databases!

New log

Attachment: mysqld-2.log (application/octet-stream, text), 301.15 KiB.

The file with SQL commands

Attachment: patch_4.3.3_00_paulo_nfse_ajustes_e_nova_tabela.sql (application/octet-stream, text), 2.58 KiB.

Hi, can it be the problem? 

Look:
http://www.speedemy.com/mysql-troubleshooting-crash-course/

Hi,

I face similar bug using 5.7.13 and 5.7.14.
When I drop a database, MySQL server was dead by Semaphore wait.

It may be mitigation to set innodb_purge_threads to 1.

I've downtraded to 5.6.39...

Please try version 5.7.19. Thanks.

We have just seen a very similar crash on 5.7.18 when dropping a database. The server is running CentOS 5, so I don't believe that upgrading to 5.7.19 is an option?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Given that we are unable to upgrade to 5.7.19, please could you let me know what additional information you would like us to provide to identify the root cause of this defect.

See https://jira.mariadb.org/browse/MDEV-14637 for the detailed analysis of a similar case. I think we have a real bug here.

I can confirm this issue with MySQL 5.7.19. When dropping a lot a databases in a short time, Semahphore issue occur and MySQL shuts down after 600 seconds. The solutions was to set innodb_purge_threads to 1 instead of 4.

Hi!

This is a duplicate bug, because it is very similar to an internal-only bug, that is not present in the public bugs database. 

I will provide the internal bug number in the hidden comment, but will update this page with public comment, once when that bug is fixed.

Do we have some info about this "internal-only bug"? Almost one year passed, we are affected by this issue and we are on the latest MySQL version avaiable.
Please provide some info.

Hi,

When the internal bug is fixed, this page will also be updated.

A duplicate of this bug is fixed in 5.7.22.

Hence, try that version .......

Fixed in 5.7.22 under the heading of

Bug#27304661 MYSQL CRASH DOING SYNC INDEX ] [FATAL] INNODB: SEMAPHORE WAIT HAS LASTED > 600

Correcting bug status to closed as per standard process.