akonadiserver lockup with sqlite

[Daniel Vrátil]

On Sunday, January 15, 2017 12:06:58 AM CET Daniel Vrátil wrote:
> On Saturday, January 14, 2017 11:23:56 PM CET David Faure wrote:
> > Hi Dan,
> > 
> > Thanks for the advice (in reply to Laurent) on how to debug command
> > handlers in akonadiserver, very useful.
> > 
> > I just used it to debug the test failure from
> > akonadi_sqlite_foldertreewidgettest, which passes with mysql
> > https://build.kde.org/job/mailcommon%20master%20kf5-qt5/119/PLATFORM=Linux
> > ,
> > compiler=gcc/testReport/(root)/TestSuite/akonadi_sqlite_foldertreewidgette
> > st / (I get the same locally, and it used to work, when I wrote that test)
> > 
> > Here's the backtrace from akonadiserver:
> > 
> > #2  0x00007f72f5b3bea3 in QWaitCondition::wait (this=0x7f72c2ffba48,
> > mutex=0x7f72c2ffba50, time=18446744073709551615) at
> > /d/qt/5/kde/qtbase/src/corelib/thread/qwaitcondition_unix.cpp:215 #3
> > 0x00007f72eb14236c in qSqlite3WaitForUnlockNotify (db=0x7f72b4004ed8) at
> > /d/kde/src/5/kde/pim/akonadi/src/qsqlite/src/sqlite_blocking.cpp:67 #4
> > 0x00007f72eb1423d2 in sqlite3_blocking_step (pStmt=0x7f72b402be98) at
> > /d/kde/src/5/kde/pim/akonadi/src/qsqlite/src/sqlite_blocking.cpp:80 #5
> > 0x00007f72eb143a6c in QSQLiteResultPrivate::fetchNext
> > (this=0x7f72b40295c0,
> > values=empty QVector<QVariant>, idx=0, initialFetch=true) at
> > /d/kde/src/5/kde/pim/akonadi/src/qsqlite/src/qsql_sqlite.cpp:311 #6
> > 0x00007f72eb1450f3 in QSQLiteResult::exec (this=0x7f72b402aab0) at
> > /d/kde/src/5/kde/pim/akonadi/src/qsqlite/src/qsql_sqlite.cpp:555 #7
> > 0x00007f72eb1444fd in QSQLiteResult::reset (this=0x7f72b402aab0,
> > query="BEGIN IMMEDIATE TRANSACTION") at
> > /d/kde/src/5/kde/pim/akonadi/src/qsqlite/src/qsql_sqlite.cpp:427 #8
> > 0x00007f72f67bcb4c in QSqlQuery::exec (this=0x7f72c2ffbfc0, query="BEGIN
> > IMMEDIATE TRANSACTION") at
> > /d/qt/5/kde/qtbase/src/sql/kernel/qsqlquery.cpp:399 #9  0x00007f72f67c0f2a
> > in QSqlDatabase::exec (this=0x7f72b40042a8, query="BEGIN IMMEDIATE
> > TRANSACTION") at /d/qt/5/kde/qtbase/src/sql/kernel/qsqldatabase.cpp:700
> > #10
> > 0x00000000004d6b27 in Akonadi::Server::DataStore::beginTransaction
> > (this=0x7f72b4004290) at
> > /d/kde/src/5/kde/pim/akonadi/src/server/storage/datastore.cpp:1352 #11
> > 0x000000000052535d in Akonadi::Server::Transaction::Transaction
> > (this=0x7f72c2ffc080, db=0x7f72b4004290, beginTransaction=true) at
> > /d/kde/src/5/kde/pim/akonadi/src/server/storage/transaction.cpp:30 #12
> > 0x000000000056ad26 in Akonadi::Server::Delete::parseStream
> > (this=0x7f72b40181e0) at
> > /d/kde/src/5/kde/pim/akonadi/src/server/handler/delete.cpp:65
> > 
> > How does that unlock-notify stuff work?
> 
> When thread A tries to run a query and gets "LOCKED" response from sqlite
> because thread B is currently holding lock on the database then thread A
> registers an unlock-notify callback and blocks (that's what you are seeing
> in the bt above). Once thread B is done with the query and releases the
> database lock it picks one of the registered unlock-notify callback and
> calls it. The callback just unlocks the mutex in the other thread and the
> thread will re-try the query, this time succesfully acquiring the DB lock.
> Once this thread is done, it picks another callback from the queue etc.
> etc.
> 
> It's a very simple mechanism, there's more here [0] if you want more
> details.
> > I don't see any other thread doing
> > anything with sqlite in the backtraces, so what is this thread waiting
> > for?
> 
> Good question :-) I don't know. Good news is that I can reproduce the
> deadlock, so I'll try to investigate what's going on.

Fixed in 6adadc171c24cdf53258939034fc213418d9e9b7. I accidentally introduced 
the deadlock recently by forgetting to commit/rollback a transaction in one 
early-return case. If the transaction acquired an exclusive lock on the table 
then the query in the backtrace above was blocked forever, hopelessly waiting 
for the SearchManager to release the lock so it can acquire it (it's a BEGIN 
TRANSACTION query).

This does not affect MySQL/PSQL in the particular case thanks to those two 
having more fine-grained locking mechanisms than SQLite, but in the real world 
it would probably lead to lock timeout errors.


Dan

> 
> Dan
> 
> 
> [0] https://www.sqlite.org/unlock_notify.html


-- 
Daniel Vrátil
www.dvratil.cz | dvratil at kde.org
IRC: dvratil on Freenode (#kde, #kontact, #akonadi, #fedora-kde)

GPG Key: 0x4D69557AECB13683
Fingerprint: 0ABD FA55 A4E6 BEA9 9A83 EA97 4D69 557A ECB1 3683
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: This is a digitally signed message part.
URL: <http://mail.kde.org/pipermail/kde-pim/attachments/20170115/80a138d7/attachment.sig>