Bug 434706

Summary: deleting mails regularly triggers mariadb transaction deadlock
Product: [Frameworks and Libraries] Akonadi Reporter: Milian Wolff <mail>
Component: serverAssignee: kdepim bugs <kdepim-bugs>
Status: REPORTED ---    
Severity: normal CC: axel.braun, hey
Priority: NOR    
Version: 5.16.3   
Target Milestone: ---   
Platform: Other   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:

Description Milian Wolff 2021-03-21 10:06:20 UTC 
SUMMARY
Quite often I'm running into transaction deadlocks when I delete spam email via `shift + delete`. When that happens a dialog pops up with an (infinite) progress bar saying "please wait while the message is transferred". The only way to get out of this situation is to cancel the operation, then quit kontact/kmail and restart it. It seems like that's enough to fix the deadlock, afterwards - i.e. even without a mariadb/akonadi restart - I can usually delete the spam with `shift + delete` just fine.

STEPS TO REPRODUCE
1. start akonadi with mariadb
2. open kmail/kontact
3. shift + delete spam mail

OBSERVED RESULT
infinite progress bar in dialog

In `journalctl -xe` I found these messages when it happened just now:
```
Mär 21 10:45:19 agathebauer kmail[1317]: org.kde.pim.akonadicore: Received response with a different tag!
Mär 21 10:46:20 agathebauer akonadi_maildispatcher_agent[1586]: void SendJob::setFrom(const QString &from)  "mail@milianw.de"
Mär 21 10:46:20 agathebauer akonadi_maildispatcher_agent[1586]: d->m_returnPath   "<mail@milianw.de>"
Mär 21 10:46:20 agathebauer akonadiserver[1305]: org.kde.pim.akonadiserver: QueryBuilder::exec(): database reported transaction deadlock, retrying transaction
Mär 21 10:46:20 agathebauer akonadiserver[1305]: org.kde.pim.akonadiserver: "Deadlock found when trying to get lock; try restarting transaction QMYSQL3: Unable to execute statement"
Mär 21 10:46:20 agathebauer akonadi_imap_resource[1583]: org.kde.pim.imapresource: "Connection to server lost."
```

I then connected to the akonadi socket with `mariadb` and ran `SHOW ENGINE INNODB STATUS`. This gave me the following output:
```
| InnoDB |      | 
=====================================
2021-03-21 10:57:00 0x7fdc8ddf1640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 135 srv_active, 0 srv_shutdown, 3646 srv_idle
srv_master_thread log flush and writes: 3781
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 75
OS WAIT ARRAY INFO: signal count 757
RW-shared spins 92, rounds 1706, OS waits 33
RW-excl spins 241, rounds 874, OS waits 23
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 18.54 RW-shared, 3.63 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2021-03-21 10:54:33 0x7fdc8f529640
*** (1) TRANSACTION:
TRANSACTION 2784938, ACTIVE 0 sec starting index read
mysql tables in use 6, locked 6
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 88, OS thread handle 140585223026240, query id 48135 localhost milian Updating
UPDATE PimItemTable SET atime = ? WHERE ( ( PimItemTable.id = ? ) )
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 7928 n bits 192 index PRIMARY of table `akonadi`.`pimitemtable` trx id 2784938 lock_mode X locks rec but not gap waiting
Record lock, heap no 19 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 8; hex 8000000000127f07; asc         ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 5; hex 3337323334; asc 37234;;
 5: SQL NULL;
 6: SQL NULL;
 7: len 8; hex 8000000000000081; asc         ;;
 8: len 8; hex 8000000000000003; asc         ;;
 9: len 4; hex 605709c9; asc `W  ;;
 10: len 4; hex 605709c9; asc `W  ;;
 11: len 1; hex 80; asc  ;;
 12: len 8; hex 800000000000716b; asc       qk;;

*** (2) TRANSACTION:
TRANSACTION 2784936, ACTIVE 0 sec starting index read
mysql tables in use 6, locked 6
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 89, OS thread handle 140585274086976, query id 48139 localhost milian Updating
UPDATE PimItemTable SET rev = ?, remoteId = ?, remoteRevision = ?, gid = ?, collectionId = ?, mimeTypeId = ?, datetime = ?, atime = ?, dirty = ?, size = ? WHERE ( id = ? )
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 26 page no 7928 n bits 192 index PRIMARY of table `akonadi`.`pimitemtable` trx id 2784936 lock_mode X locks rec but not gap
Record lock, heap no 19 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 8; hex 8000000000127f07; asc         ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 5; hex 3337323334; asc 37234;;
 5: SQL NULL;
 6: SQL NULL;
 7: len 8; hex 8000000000000081; asc         ;;
 8: len 8; hex 8000000000000003; asc         ;;
 9: len 4; hex 605709c9; asc `W  ;;
 10: len 4; hex 605709c9; asc `W  ;;
 11: len 1; hex 80; asc  ;;
 12: len 8; hex 800000000000716b; asc       qk;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 26 page no 7650 n bits 1112 index PimItemTable_idSortIndex of table `akonadi`.`pimitemtable` trx id 2784936 lock_mode X locks rec but not gap waiting
Record lock, heap no 948 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 8000000000127f07; asc         ;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 2784989
Purge done for trx's n:o < 2784989 undo n:o < 0 state: running
History list length 4
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422060467078680, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467121320, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467117056, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467112792, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467082944, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467061624, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467108528, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467104264, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467100000, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467095736, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467091472, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467087208, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467074416, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467070152, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467065888, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467155432, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467057360, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467053096, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467048832, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422060467044568, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
Pending normal aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
277927 OS file reads, 1101 OS file writes, 206 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 5, free list len 544, seg size 550, 26 merges
merged operations:
 insert 82, delete mark 154, delete 133
discarded operations:
 insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 8488738784
Log flushed up to   8488738784
Pages flushed up to 8488068579
Last checkpoint at  8488068460
0 pending log flushes, 0 pending chkp writes
635 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 136314880
Dictionary memory allocated 909864
Buffer pool size   8065
Free buffers       0
Database pages     8065
Old database pages 2957
Modified db pages  275
Percent of dirty pages(LRU & free pages): 3.409
Max dirty pages percent: 90.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 8037, not young 14011713
0.00 youngs/s, 0.00 non-youngs/s
Pages read 277884, created 173, written 455
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: 8065, unzip_LRU len: 0
I/O sum[25]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 read views open inside InnoDB
Process ID=0, Main thread ID=0, state: sleeping
Number of rows inserted 484, updated 681, deleted 269, read 27172097
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
```

EXPECTED RESULT
no deadlock

SOFTWARE/OS VERSIONS
Linux/KDE Plasma: 5.10.24-1-lts
KDE Plasma Version: 5.21.3
KDE Frameworks Version: 5.21.3
Qt Version: 5.15.2
mariadb 15.1
Comment 1 Axel Braun 2024-04-18 08:04:37 UTC 
This annoying problem occurs as well with postgres (which I use as backend), even in latest version, and independent if I use shift-del or just delete. aonadictl fsck|vaccum does not help, partly restarting the akonadi server helps, but thats not granted.
If one lets me know how I can debug that issue, happy to do!

Operating System: openSUSE Tumbleweed 20240416
KDE Plasma Version: 6.0.3
KDE Frameworks Version: 6.1.0
Qt Version: 6.7.0