0

Running MySQL 5.7.15 with InnoDB, any queries which modify any of the database tables (eg. insert, update, delete) run indefinitely and never complete. Queries which do not modify the data (eg. select) run without any issues. This problem persists over restarting MySQL and the server it is running on.

'show full processlist' has no additional queries, and the insert/update/delete queries, when killed in mysql, remain in this table (marked as killed).

The following is the 'show engine innodb status' output:

=====================================
 2016-10-12 15:38:19 0x7f8fce613700 INNODB MONITOR OUTPUT
 =====================================
 Per second averages calculated from the last 4541 seconds
 -----------------
 BACKGROUND THREAD
 -----------------
 srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 1 srv_idle
 srv_master_thread log flush and writes: 1
 ----------
 SEMAPHORES
 ----------
 OS WAIT ARRAY INFO: reservation count 223
 --Thread 140255654102784 has waited at row0purge.cc line 461 for -22565.00 seconds the semaphore:
 SX-lock on RW-latch at 0x7f8fa0020e80 created in file dict0dict.cc line 2687
 a writer (thread id 140255645710080) has reserved it in mode  exclusive
 number of readers 0, waiters flag 1, lock_word: 0
 Last time read locked in file gis0sea.cc line 134
 Last time write locked in file /build/mysql-5.7-Cv39zG/mysql-5.7-5.7.13/storage/innobase/btr/btr0cur.cc line 974
 --Thread 140255670888192 has waited at row0purge.cc line 461 for -22565.00 seconds the semaphore:
 SX-lock on RW-latch at 0x7f8fa0020e80 created in file dict0dict.cc line 2687
 a writer (thread id 140255645710080) has reserved it in mode  exclusive
 number of readers 0, waiters flag 1, lock_word: 0
 Last time read locked in file gis0sea.cc line 134
 Last time write locked in file /build/mysql-5.7-Cv39zG/mysql-5.7-5.7.13/storage/innobase/btr/btr0cur.cc line 974
 --Thread 140255662495488 has waited at row0purge.cc line 461 for -22565.00 seconds the semaphore:
 SX-lock on RW-latch at 0x7f8fa0020e80 created in file dict0dict.cc line 2687
 a writer (thread id 140255645710080) has reserved it in mode  exclusive
 number of readers 0, waiters flag 1, lock_word: 0
 Last time read locked in file gis0sea.cc line 134
 Last time write locked in file /build/mysql-5.7-Cv39zG/mysql-5.7-5.7.13/storage/innobase/btr/btr0cur.cc line 974
 --Thread 140255679280896 has waited at srv0srv.cc line 1968 for -22566.00 seconds the semaphore:
 X-lock (wait_ex) on RW-latch at 0x955b1b8 created in file dict0dict.cc line 1184
 a writer (thread id 140255679280896) has reserved it in mode  wait exclusive
 number of readers 4, waiters flag 1, lock_word: fffffffffffffffc
 Last time read locked in file row0purge.cc line 853
 Last time write locked in file /build/mysql-5.7-Cv39zG/mysql-5.7-5.7.13/storage/innobase/fts/fts0fts.cc line 7507
 --Thread 140255619729152 has waited at row0mysql.cc line 2442 for 5964.00 seconds the semaphore:
 S-lock on RW-latch at 0x955b1b8 created in file dict0dict.cc line 1184
 a writer (thread id 140255679280896) has reserved it in mode  wait exclusive
 number of readers 4, waiters flag 1, lock_word: fffffffffffffffc
 Last time read locked in file row0purge.cc line 853
 Last time write locked in file /build/mysql-5.7-Cv39zG/mysql-5.7-5.7.13/storage/innobase/fts/fts0fts.cc line 7507
 OS WAIT ARRAY INFO: signal count 123
 RW-shared spins 0, rounds 29, OS waits 8
 RW-excl spins 0, rounds 214, OS waits 2
 RW-sx spins 167, rounds 5010, OS waits 167
 Spin rounds per wait: 29.00 RW-shared, 214.00 RW-excl, 30.00 RW-sx
 ------------
 TRANSACTIONS
 ------------
 Trx id counter 29938446
 Purge done for trx's n:o < 29933558 undo n:o < 11747 state: running
 History list length 610
 LIST OF TRANSACTIONS FOR EACH SESSION:
 ---TRANSACTION 421735190197696, not started
 0 lock struct(s), heap size 1136, 0 row lock(s)
 ---TRANSACTION 421735190194016, not started
 0 lock struct(s), heap size 1136, 0 row lock(s)
 ---TRANSACTION 421735190196776, not started
 0 lock struct(s), heap size 1136, 0 row lock(s)
 ---TRANSACTION 421735190195856, not started
 0 lock struct(s), heap size 1136, 0 row lock(s)
 ---TRANSACTION 29938444, ACTIVE 5964 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 6, OS thread handle 140255619729152, query id 129 10.0.2.1 salus updating
 DELETE FROM `user_data`.`Users` WHERE `username`='some_username'
 TABLE LOCK table `user_data`.`Users` trx id 29938444 lock mode IX
 RECORD LOCKS space id 103 page no 3 n bits 144 index PRIMARY of table `salus_user_data`.`Users` trx id 29938444 lock_mode X locks rec but not gap
 Record lock, heap no 3 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
  0: len 30; hex 31586f3265526a784830695565365359696546646476716630562b4a3845; asc 1Xo2eRjxH0iUe6SYieFddvqf0V+J8E; (total 88 bytes);
  1: len 6; hex 000000001ff8; asc       ;;
  2: len 7; hex a80000011c0144; asc       D;;

 --------
 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
 3644 OS file reads, 66 OS file writes, 14 OS fsyncs
 0.13 reads/s, 16384 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
 -------------------------------------
 INSERT BUFFER AND ADAPTIVE HASH INDEX
 -------------------------------------
 Ibuf: size 1, free list len 1721, seg size 1723, 0 merges
 merged operations:
  insert 0, delete mark 0, delete 0
 discarded operations:
  insert 0, delete mark 0, delete 0
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 Hash table size 1182691, node heap has 0 buffer(s)
 0.00 hash searches/s, 1.83 non-hash searches/s
 ---
 LOG
 ---
 Log sequence number 4716266357
 Log flushed up to   4716266357
 Pages flushed up to 4716266357
 Last checkpoint at  4713074949
 0 pending log flushes, 0 pending chkp writes
 57 log i/o's done, 0.00 log i/o's/second
 ----------------------
 BUFFER POOL AND MEMORY
 ----------------------
 Total large memory allocated 4397727744
 Dictionary memory allocated 1031417
 Buffer pool size   262112
 Free buffers       258706
 Database pages     3406
 Old database pages 211
 Modified db pages  18
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 3356, created 50, written 47
 0.13 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 3406, unzip_LRU len: 0
 I/O sum[0]:cur[5552], unzip sum[0]:cur[0]
 ----------------------
 INDIVIDUAL BUFFER POOL INFO
 ----------------------
 ---BUFFER POOL 0
 Buffer pool size   32764
 Free buffers       32386
 Database pages     378
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 378, created 0, written 3
 0.02 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 936 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 378, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 1
 Buffer pool size   32764
 Free buffers       32361
 Database pages     403
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 403, created 0, written 5
 0.02 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 982 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 403, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 2
 Buffer pool size   32764
 Free buffers       32364
 Database pages     400
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 400, created 0, written 1
 0.02 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 940 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 400, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 3
 Buffer pool size   32764
 Free buffers       32323
 Database pages     441
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 441, created 0, written 0
 0.01 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 998 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 441, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 4
 Buffer pool size   32764
 Free buffers       32246
 Database pages     518
 Old database pages 211
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 518, created 0, written 0
 0.02 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 874 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 518, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 5
 Buffer pool size   32764
 Free buffers       32359
 Database pages     405
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 405, created 0, written 0
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 994 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 405, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 6
 Buffer pool size   32764
 Free buffers       32388
 Database pages     376
 Old database pages 0
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 376, created 0, written 3
 0.01 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 949 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 376, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 ---BUFFER POOL 7
 Buffer pool size   32764
 Free buffers       32279
 Database pages     485
 Old database pages 0
 Modified db pages  18
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 0, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 435, created 50, written 35
 0.02 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 990 / 1000, young-making rate 0 / 1000 not 0 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 485, unzip_LRU len: 0
 I/O sum[0]:cur[694], unzip sum[0]:cur[0]
 --------------
 ROW OPERATIONS
 --------------
 0 queries inside InnoDB, 0 queries in queue
 0 read views open inside InnoDB
 Process ID=1009, Main thread ID=140255679280896, state: enforcing dict cache limit
 Number of rows inserted 2138, updated 0, deleted 0, read 11760
 0.33 inserts/s, 0.00 updates/s, 0.00 deletes/s, 2.15 reads/s
 ----------------------------
 END OF INNODB MONITOR OUTPUT
 ============================

Which has some interesting entries - there are threads which wait large negative times for a lock which that thread has reserved in mode wait exclusive. This seems to be the lock which the thread with the insert/delete/update transaction is waiting on.

0

Something is really weird in your server as you should never see such big number in message:

Per second averages calculated from the last 4541 seconds

Usually the number is within a minute or few seconds. Another bad symptom is state of main thread

enforcing dict cache limit

If you start seeing such status all the time that is good chance that some internal deadlock happened or memory corruption or bug etc.

The only thing I may recommend is to restart and try to find out what triggers such bad state. Maybe try upgrade / downgrade, but that is usually tricky path.

  • Thanks for your answer. Even after a restart the server was in the same state, and the original issue only occurred a couple of times, so it would have been very difficult to figure out what triggered it. As it is I replaced the MySQL database with a MongoDB one, as it seems to be more suited for the task. – gfkeith Mar 16 '17 at 2:28
  • yeah some tasks don't require relational model and integrity checks - good luck with that – noonex Mar 16 '17 at 8:27

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.