France-ioi / AlgoreaBackend

Backend for the new Algorea platform
MIT License
1 stars 2 forks source link

Deadlock on answers (?) #1049

Open smadbe opened 5 months ago

smadbe commented 5 months ago

Deadlock reported in MySQL: (seems to occur when we had the request blocking the CPU for 250sec)

=====================================
2024-04-03 14:49:47 22565620258560 INNODB MONITOR OUTPUT
=====================================
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-04-03 14:38:06 22565623953152
*** (1) TRANSACTION:
TRANSACTION 46164599, ACTIVE 40 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 8537, OS thread handle 22565554472704, query id 7778150 ....amazonaws.com 18.194.8.137 algorea-backend updating
DELETE FROM `answers`  WHERE (answers.author_id = 8261539541874994066) AND (answers.attempt_id = 0) AND (answers.participant_id = 8261539541874994066) AND (answers.item_id = 99075885434228761) AND (answers.type = 'Current')

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 4668 page no 79360 n bits 440 index type_participant_id_item_id_created_at_desc_attempt_id_desc of table `algorea_full`.`answers` trx id 46164599 lock_mode X waiting
Record lock, heap no 58 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e94c; asc     L;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex e2a4c790baaaebd3; asc         ;;

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 4668 page no 79360 n bits 440 index type_participant_id_item_id_created_at_desc_attempt_id_desc of table `algorea_full`.`answers` trx id 46164599 lock_mode X waiting
Record lock, heap no 58 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e94c; asc     L;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex e2a4c790baaaebd3; asc         ;;

*** (2) TRANSACTION:
TRANSACTION 46164593, ACTIVE 48 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 11 lock struct(s), heap size 1128, 13 row lock(s), undo log entries 2
MySQL thread id 8534, OS thread handle 22564372723456, query id 7778088 ....amazonaws.com 3.127.210.153 algorea-backend update
INSERT INTO `answers` (`answer`, `attempt_id`, `author_id`, `created_at`, `id`, `item_id`, `participant_id`, `state`, `type`) VALUES ('{\"idSubmission\":\"559266491122123621\",\"langProg\":\"c\",\"sourceCode\":\"#include <stdio.h>\\nint main() {\\n    int height = 0;\\n    int nbLeaflets = 0;\\n    scanf(\\\"%d %d\\\", &height, &nbLeaflets);\\n    int tinuviel = height <= 5 && nbLeaflets >= 8;\\n    int calaelen = height >= 10 && nbLeaflets >= 10;\\n    int falarion = height <= 8 && nbLeaflets <= 5;\\n    int dorthonion = height >= 12 && nbLeaflets <= 7;\\n    if(tinuviel) {\\n        printf(\\\"Tinuviel\\\");\\n    }\\n    if(calaelen){\\n        printf(\\\"Calaelen\\\");\\n    }\\n    if(falarion){\\n        printf(\\\"Falarion\\\");\\n    }\\n    if(dorthonion){\\n        printf(\\\"Dorthonion\\\");\\n    }\\n    if(!tinuviel && !calaelen && !fal

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 4668 page no 79360 n bits 440 index type_participant_id_item_id_created_at_desc_attempt_id_desc of table `algorea_full`.`answers` trx id 46164593 lock_mode X
Record lock, heap no 38 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e879; asc     y;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex df38c10307bf29d9; asc  8    ) ;;

Record lock, heap no 53 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e8a0; asc      ;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex 84564042ce98a2d8; asc  V@B    ;;

Record lock, heap no 54 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e8d8; asc      ;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex e9f5775f9f1f11cd; asc   w_    ;;

Record lock, heap no 55 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e8d8; asc      ;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex 90e4912ccbee9bce; asc    ,    ;;

Record lock, heap no 56 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e949; asc     I;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex 92500fc182f6a322; asc  P     ";;

Record lock, heap no 57 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e94a; asc     J;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex f7d52d7c60776d2e; asc   -|`wm.;;

Record lock, heap no 58 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e94c; asc     L;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex e2a4c790baaaebd3; asc         ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 4668 page no 79360 n bits 440 index type_participant_id_item_id_created_at_desc_attempt_id_desc of table `algorea_full`.`answers` trx id 46164593 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 58 PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 1; hex 03; asc  ;;
 1: len 8; hex f2a6e2711b4d6b92; asc    q Mk ;;
 2: len 8; hex 815ffcfe2d1d5019; asc  _  - P ;;
 3: len 5; hex 99b306e94c; asc     L;;
 4: len 8; hex 8000000000000000; asc         ;;
 5: len 8; hex e2a4c790baaaebd3; asc         ;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 46164690
Purge done for trx's n:o < 46164690 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 304043108866408, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108865600, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108868832, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108869640, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108864792, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108863984, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108867216, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108863176, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108870448, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108862368, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 304043108861560, not started
0 lock struct(s), heap size 1128, 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: 1016
1570132 OS file reads, 7639954 OS file writes, 1585362 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 31724, seg size 31726, 61282 merges
merged operations:
 insert 18016, delete mark 13346837, delete 2
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 553253, node heap has 65 buffer(s)
Hash table size 553253, node heap has 49 buffer(s)
Hash table size 553253, node heap has 370 buffer(s)
Hash table size 553253, node heap has 6586 buffer(s)
Hash table size 553253, node heap has 149 buffer(s)
Hash table size 553253, node heap has 1657 buffer(s)
Hash table size 553253, node heap has 184 buffer(s)
Hash table size 553253, node heap has 4 buffer(s)
1.00 hash searches/s, 0.50 non-hash searches/s
---
LOG
---
Log sequence number          190952529975
Log buffer assigned up to    190952529975
Log buffer completed up to   190952529975
Log written up to            190952529975
Log flushed up to            190952529975
Added dirty pages up to      190952529975
Pages flushed up to          190949634747
Last checkpoint at           190949634747
4405101 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1444665
Buffer pool size   131067
Free buffers       8194
Database pages     113809
Old database pages 41848
Modified db pages  2155
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 34753771, not young 405755577
3.98 youngs/s, 0.00 non-youngs/s
Pages read 1568795, created 77192, written 2871158
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 67 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 113809, unzip_LRU len: 0
I/O sum[624]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   16384
Free buffers       1024
Database pages     14223
Old database pages 5230
Modified db pages  363
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4206932, not young 197541311
0.00 youngs/s, 0.00 non-youngs/s
Pages read 622901, created 9663, written 337865
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: 14223, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   16382
Free buffers       1025
Database pages     14231
Old database pages 5233
Modified db pages  196
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4006383, not young 24856367
0.00 youngs/s, 0.00 non-youngs/s
Pages read 130430, created 9611, written 351303
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: 14231, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   16382
Free buffers       1024
Database pages     14236
Old database pages 5235
Modified db pages  259
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7224243, not young 46264693
3.98 youngs/s, 0.00 non-youngs/s
Pages read 141668, created 9040, written 372373
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 71 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 14236, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   16384
Free buffers       1025
Database pages     14228
Old database pages 5232
Modified db pages  237
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3818419, not young 21518795
0.00 youngs/s, 0.00 non-youngs/s
Pages read 135323, created 9532, written 364324
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: 14228, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   16384
Free buffers       1024
Database pages     14222
Old database pages 5229
Modified db pages  180
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3764403, not young 22961580
0.00 youngs/s, 0.00 non-youngs/s
Pages read 121381, created 10001, written 343436
0.00 reads/s, 0.00 creates/s, 0.00 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: 14222, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   16383
Free buffers       1024
Database pages     14215
Old database pages 5227
Modified db pages  206
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3838689, not young 24442417
0.00 youngs/s, 0.00 non-youngs/s
Pages read 128018, created 9945, written 346450
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: 14215, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   16384
Free buffers       1024
Database pages     14222
Old database pages 5229
Modified db pages  320
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4034064, not young 46416082
0.00 youngs/s, 0.00 non-youngs/s
Pages read 139026, created 9525, written 354867
0.00 reads/s, 0.00 creates/s, 0.00 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: 14222, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   16384
Free buffers       1024
Database pages     14232
Old database pages 5233
Modified db pages  394
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3860638, not young 21754332
0.00 youngs/s, 0.00 non-youngs/s
Pages read 150048, created 9875, written 400540
0.00 reads/s, 0.00 creates/s, 0.00 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: 14232, unzip_LRU len: 0
I/O sum[78]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=770, Main thread ID=22565565228800 , state=sleeping
Number of rows inserted 32347609, updated 875150, deleted 6989014, read 9548949137
42.99 inserts/s, 0.00 updates/s, 0.00 deletes/s, 42.99 reads/s
Number of system rows inserted 10, updated 2847, deleted 12, read 588088
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 1.25 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================