I am using MariaDB 10.4.12-MariaDB-1:10.4.12+maria~stretch-log with innodb on a debian stretch.
I am facing a problem of very slow insert/update/delete queries that take more than 10 seconds but does not appear in the slow query log.
These long time running requests happen ONLY when the server receive more requests as usual ( about 20/s ).
The variables for logging slow requests are as follow :
MariaDB [(none)]> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.001 sec)
For instance, the following update statement is very simple and use the primary key of the table :
delete from WEDMATTP Where AttRef like 'EDM-%-FOLDER' and DocId in( 1638486)
There is actually NO records with AttRef like 'EDM-%-FOLDER' and there was only one for DocId in( 1638486)
The EXPLAIN command says :
+------+-------------+----------+-------+-------------------------+---------+---------+------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+----------+-------+-------------------------+---------+---------+------+------+-------------+
| 1 | SIMPLE | WEDMATTP | range | PRIMARY,WEDMATTP_DocNum | PRIMARY | 70 | NULL | 1 | Using where |
+------+-------------+----------+-------+-------------------------+---------+---------+------+------+-------------+
1 row in set (0.001 sec)
The table was created as follow :
MariaDB [abngmadbprod]> show create table wedmattp\G
*************************** 1. row ***************************
Table: wedmattp
Create Table: CREATE TABLE "wedmattp" (
"DocId" int(11) NOT NULL,
"AttRef" varchar(64) NOT NULL,
"AttDate" varchar(14) NOT NULL,
"AttUser" varchar(20) DEFAULT NULL,
"AttMode" varchar(1) DEFAULT NULL,
"UsrId" int(11) DEFAULT NULL,
"AttEndDate" varchar(14) DEFAULT NULL,
PRIMARY KEY ("DocId","AttRef"),
KEY "WEDMATTP_DocNum" ("AttRef"),
KEY "WEDMATTP_AttDate" ("AttDate"),
KEY "WEDMATTP_Usr" ("UsrId"),
KEY "WEDMATTP_AttUser" ("AttUser"),
CONSTRAINT "FK_DocAtt" FOREIGN KEY ("DocId") REFERENCES "wedmdocp" ("DocId")
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.483 sec)
BUT when I look at the processes while this request is running :
Id User Host db Command Time State Info Progress
1 system user NULL Daemon NULL InnoDB purge coordinator NULL 0.000
2 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
3 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
4 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
5 system user NULL Daemon NULL InnoDB shutdown handler NULL 0.000
13 repl srvdatae.antemeta.lan:46504 NULL Binlog Dump 105901 Master has sent all binlog to slave; waiting for binlog to be updated NULL 0.000
325584 wyxuser_g_abn srvappd:39384 abnwyxdbprod Sleep 30 NULL 0.000
325589 wyxuser_g_abn srvappe:57448 abnwyxdbprod Sleep 30 NULL 0.000
325663 wyxuser_ph_edm srvappe:57526 abnwyxdbprod Query 14 Updating delete from WEDMATTP Where AttRef like 'EDM-%-FOLDER' and DocId in( 1638486) 0.000
325673 wyxuser_ph_edm srvappd:39468 abnwyxdbprod Query 14 Waiting for table level lock INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode ) \n VALUES (1638487, 'WYX-10701/GLI-448398-DAT', '20211129081046', '-NESTOR-BURMA-', 'P') 0.000
326176 wyxuser_g_abn srvappe:58170 abnwyxdbprod Sleep 8 NULL 0.000
326199 wyxuser_g_abn srvappe:58208 abnwyxdbprod Sleep 7 NULL 0.000
326290 wyxuser_ph_edm srvappe:58302 abnwyxdbprod Query 3 Waiting for table level lock insert into WEDMITMP(StkId,ItmId,ItmDate,ItmOrder) values( 7503,1638488,\n'20211129081058', 0 ) 0.000
326308 wyxuser_ph_edm srvappe:58330 abnwyxdbprod Query 3 Waiting for table level lock insert into WEDMITMP(StkId,ItmId,ItmDate,ItmOrder) values( 7503,1638489,\n'20211129081058', 0 ) 0.000
326441 wyxuser_g_oauth srvappd:40056 oauth2prod Sleep 0 NULL 0.000
326457 wyxuser_g_admin srvappd:40088 adminwyxdbprod Sleep 0 NULL 0.000
326458 root localhost NULL Query 0 Init show full processlist 0.000
The request was running for 14 seconds when I looked at the process but it does not appears in the slow logs. It usually run very fast but not at that moment. And the serveur does not seems to be very loaded (only 4 requests running).
Some other common request that run fast (<1s) most of the time may take more than 60s in these kind of situation.
I suspected a dead-lock but in the case of the show processlist above, could it be possible to have a deadlock if the delete request is currently in "Updating" state ?
Sorry to reply very late. I was waiting for the error to occur again to be able to provide the innodb status.
Dimension of the table wedmattp select count(*) from wedmattp more than 1700000 rows.
I can't tell the result of SELECT COUNT(*) FROM wedmattp WHERE DocId in( 1638486) for this specific value of Docid but 99% of Docid have less than 7 rows.
All our client connections are explicitely in latin1.
Here the new log I got with the innodb status while the error (long request) occurs. First the show processlist
=== mercredi 1 décembre 2021, 07:03:01 (UTC+0100)
Id User Host db Command Time State Info Progress
1 system user NULL Daemon NULL InnoDB purge coordinator NULL 0.000
2 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
3 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
4 system user NULL Daemon NULL InnoDB purge worker NULL 0.000
5 system user NULL Daemon NULL InnoDB shutdown handler NULL 0.000
13 repl srvdatae.antemeta.lan:46504 NULL Binlog Dump 271021 Master has sent all binlog to slave; waiting for binlog to be updated NULL 0.000
1714646 wyxuser_g_abn srvappe:42218 abnwyxdbprod Sleep 33 NULL 0.000
1714673 wyxuser_g_abn srvappe:42252 abnwyxdbprod Sleep 31 NULL 0.000
1714677 wyxuser_ph_edm srvappe:42260 abnwyxdbprod Sleep 30 NULL 0.000
1714682 wyxuser_g_abn srvappe:42270 abnwyxdbprod Sleep 30 NULL 0.000
1714685 wyxuser_ph_edm srvappe:42276 abnwyxdbprod Query 29 Waiting for table level lock INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode ) \n VALUES (1648830, 'WYX-16665/GLI-845449-DAT', '20211201060231', '-NESTOR-BURMA-', 'P') 0.000
1714695 wyxuser_ph_edm srvappe:42288 abnwyxdbprod Query 29 Update INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode ) \n VALUES (1648831, 'WYX-3315/251985-CHR', '20211201060231', '-NESTOR-BURMA-', 'P') 0.000
1714702 wyxuser_g_abn srvappe:42302 abnwyxdbprod Sleep 26 NULL 0.000
1714711 wyxuser_ph_edm srvappe:42320 abnwyxdbprod Query 25 Waiting for table level lock INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode ) \n VALUES (1648832, 'WYX-10012/FAC-72539-DAT', '20211201060236', 'DR7FFC49', 'P') 0.000
1714784 root localhost NULL Query 0 Init show full processlist 0.000
The ps for the mariadb process (I got 2 MariaDB serveurs on the VM).
PID TID PRI PSR %CPU STAT COMMAND
33006 33006 19 0 4.7 Ssl /usr/sbin/mysqld
33176 33176 19 0 0.9 Ssl /usr/sbin/mysqld --defaults-file=/etc/mysql/my.prep.cnf
then the show engine innodb status
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2021-12-01 07:03:01 0x7f0f045ba700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 60 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 64402 srv_active, 0 srv_shutdown, 206431 srv_idle
srv_master_thread log flush and writes: 270771
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2448713
OS WAIT ARRAY INFO: signal count 1451239
RW-shared spins 0, rounds 93744, OS waits 30846
RW-excl spins 0, rounds 71000, OS waits 1448
RW-sx spins 640, rounds 15776, OS waits 386
Spin rounds per wait: 93744.00 RW-shared, 71000.00 RW-excl, 24.65 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2021-11-29 17:23:12 0x7f10a063b700 Transaction:
TRANSACTION 48868328, ACTIVE 1 sec updating or deleting
mysql tables in use 2, locked 2
36 lock struct(s), heap size 3520, 24 row lock(s), undo log entries 7
MySQL thread id 712238, OS thread handle 139709387093760, query id 5527984 srvappe 10.100.15.22 wyxuser_g_abn Updating
Delete from exercice where
AbnId=13118
and ExrId=712495
and AbnId = 13118
Foreign key constraint fails for table "abnwyxdbprod"."documentcomptable":
,
CONSTRAINT "FK_DCTEXR" FOREIGN KEY ("AbnId", "ExrId") REFERENCES "exercice" ("ABNID", "EXRID")
Trying to delete or update in parent table, in index PRIMARY tuple:
DATA TUPLE: 19 fields;
0: len 8; hex 800000000000333e; asc 3>;;
1: len 4; hex 800adf2f; asc /;;
2: len 6; hex 000002e9abe8; asc ;;
3: len 7; hex 7300001d6c2404; asc s l$ ;;
4: len 4; hex 800934d9; asc 4 ;;
5: len 3; hex 8fcb1f; asc ;;
6: SQL NULL;
7: SQL NULL;
8: SQL NULL;
9: SQL NULL;
10: SQL NULL;
11: SQL NULL;
12: SQL NULL;
13: len 3; hex 8fc921; asc !;;
14: len 5; hex 99aa84cbe4; asc ;;
15: SQL NULL;
16: len 8; hex 8000000000000ff0; asc ;;
17: SQL NULL;
18: SQL NULL;
But in child table "abnwyxdbprod"."documentcomptable", in index FK_DCTEXR, there is a record:
PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 800000000000333e; asc 3>;;
1: len 4; hex 800adf2f; asc /;;
2: len 4; hex 80008c0c; asc ;;
------------
TRANSACTIONS
------------
Trx id counter 49129983
Purge done for trx's n:o < 49129967 undo n:o < 0 state: running but idle
History list length 6
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421184365078104, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421184365073848, not started
mysql tables in use 2, locked 2
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421184365069592, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 49129968, ACTIVE 30 sec inserting
mysql tables in use 2, locked 2
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 1714695, OS thread handle 139702474045184, query id 13382588 srvappe 10.100.15.22 wyxuser_ph_edm Update
INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode )
VALUES (1648831, 'WYX-3315/251985-CHR', '20211201060231', '-NESTOR-BURMA-', 'P')
------- TRX HAS BEEN WAITING 30 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2184 page no 35846 n bits 88 index PRIMARY of table "abnwyxdbprod"."wedmattp" trx id 49129968 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
------------------
---TRANSACTION 49129964, ACTIVE 30 sec
mysql tables in use 2, locked 2
9 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 5
MySQL thread id 1714685, OS thread handle 139702475888384, query id 13382604 srvappe 10.100.15.22 wyxuser_ph_edm Waiting for table level lock
INSERT ignore INTO WEDMATTP (DocId, AttRef, AttDate,AttUser, AttMode )
VALUES (1648830, 'WYX-16665/GLI-845449-DAT', '20211201060231', '-NESTOR-BURMA-', 'P')
Trx read view will not see trx with id >= 49129964, sees < 49129964
---TRANSACTION 49129965, ACTIVE 30 sec
5 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 1714682, OS thread handle 139702634723072, query id 13382505 srvappe 10.100.15.22 wyxuser_g_abn
Trx read view will not see trx with id >= 49129964, sees < 49129964
---TRANSACTION 421184365056824, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421184365048312, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421184365044056, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421184365039800, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
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
239885 OS file reads, 1261322 OS file writes, 792802 OS fsyncs
0.03 reads/s, 16384 avg bytes/read, 23.67 writes/s, 11.38 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 2465, seg size 2467, 5023 merges
merged operations:
insert 7935, delete mark 538, delete 64
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 1593833, node heap has 5997 buffer(s)
Hash table size 1593833, node heap has 672 buffer(s)
Hash table size 1593833, node heap has 1167 buffer(s)
Hash table size 1593833, node heap has 3436 buffer(s)
Hash table size 1593833, node heap has 856 buffer(s)
Hash table size 1593833, node heap has 3387 buffer(s)
Hash table size 1593833, node heap has 603 buffer(s)
Hash table size 1593833, node heap has 1399 buffer(s)
13150.30 hash searches/s, 639.77 non-hash searches/s
---
LOG
---
Log sequence number 35793553330
Log flushed up to 35793553330
Pages flushed up to 35793553330
Last checkpoint at 35793553321
0 pending log flushes, 0 pending chkp writes
323373 log i/o's done, 4.05 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 6476005376
Dictionary memory allocated 729456
Buffer pool size 384720
Free buffers 114421
Database pages 252782
Old database pages 93407
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 983, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 239608, created 13174, written 794983
0.03 reads/s, 0.03 creates/s, 18.28 writes/s
Buffer pool hit rate 999 / 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: 252782, 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 48090
Free buffers 14073
Database pages 31811
Old database pages 11759
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 112, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 30092, created 1719, written 131533
0.02 reads/s, 0.02 creates/s, 4.47 writes/s
Buffer pool hit rate 999 / 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: 31811, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 48090
Free buffers 14285
Database pages 31624
Old database pages 11692
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 111, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 29985, created 1639, written 95837
0.00 reads/s, 0.00 creates/s, 0.93 writes/s
Buffer pool hit rate 1000 / 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: 31624, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 48090
Free buffers 14213
Database pages 31657
Old database pages 11705
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 119, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 30089, created 1568, written 56444
0.00 reads/s, 0.00 creates/s, 1.60 writes/s
Buffer pool hit rate 1000 / 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: 31657, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 48090
Free buffers 15270
Database pages 30638
Old database pages 11323
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 136, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 28829, created 1809, written 172234
0.02 reads/s, 0.00 creates/s, 4.33 writes/s
Buffer pool hit rate 999 / 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: 30638, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 48090
Free buffers 14058
Database pages 31870
Old database pages 11768
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 137, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 30401, created 1469, written 111736
0.00 reads/s, 0.02 creates/s, 2.68 writes/s
Buffer pool hit rate 1000 / 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: 31870, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 48090
Free buffers 13700
Database pages 32215
Old database pages 11911
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 131, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 30630, created 1585, written 91920
0.00 reads/s, 0.00 creates/s, 1.95 writes/s
Buffer pool hit rate 1000 / 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: 32215, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 48090
Free buffers 14818
Database pages 31074
Old database pages 11489
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 116, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 29606, created 1468, written 67979
0.00 reads/s, 0.00 creates/s, 1.57 writes/s
Buffer pool hit rate 1000 / 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: 31074, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 48090
Free buffers 14004
Database pages 31893
Old database pages 11760
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 121, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 29976, created 1917, written 67300
0.00 reads/s, 0.00 creates/s, 0.75 writes/s
Buffer pool hit rate 1000 / 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: 31893, 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
2 read views open inside InnoDB
Process ID=33006, Main thread ID=139702735435520, state: sleeping
Number of rows inserted 296865, updated 190576, deleted 9070, read 8255654063
2.97 inserts/s, 1.15 updates/s, 0.03 deletes/s, 59423.73 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 5378
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
If mysqld crashes before a query finishes, that query does not get written to the slowlog. This is an unfortunate fact -- sometimes a long-running query is a factor in causing a crash.
If it did not crash, then we will look deeper.
Please provide SELECT COUNT(*) FROM wedmattp WHERE DocId in( 1638486).
And... SHOW ENGINE=InnoDB STATUS; during and/or after the Delete is run.
It is not obvious what is causing "Waiting for table level lock", but the Delete is implicated.
What CHARACTER SET is the connection (for the Delete) using when connecting?
Meanwhile, I recommend lowering long_query_time to 1. (It won't help the current issue, but will help you find more slow queries.)
More
The EXPLAIN command says
Was that EXPLAIN UPDATE... or EXPLAIN against an equivalent Select?
Please turn on Explains in the slow log for when we can get something showing there. (I think it is something like log_slow_verbosity=explain)
Meanwhile, do SHOW EXPLAIN to get info on the running query.