akonadiserver lockup with sqlite

[Daniel Vrátil]

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_foldertreewidgettest
> / (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.

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/8ecf66c5/attachment.sig>