database is locked when importing two tilt series movies in 3.11.1

[yghorbal]

Hi,

I've noticed a weird issue when importing two titlt series movies (ProtImportTsMovies protocol) using scipion 3.7.1 and pyworkflow 3.11.1.
The import gets stuck for long minutes before issuing multiple database is locked statements and ends up failing.

Trying to update outputTiltSeriesM (output) of protocol tomo - import tilt-series movies, attempt=1: database is locked
Trying to update outputTiltSeriesM (output) of protocol tomo - import tilt-series movies, attempt=2: database is locked
Trying to update outputTiltSeriesM (output) of protocol tomo - import tilt-series movies, attempt=3: database is locked

The full run.stdout.log is attached (with DEBUG enabled and SCIPION_DEBUG_SQLITE set)

The same import with pyworkflow 3.10.6 works as expected (import takes seconds)
The same import with pyworkflow 3.11.1 succeeds when adding journal_mode: WAL to the pragmas dict in

scipion-pyworkflow/pyworkflow/mapper/sqlite.py

Line 814 in 8a2aa86

pragmas = {

The CHANGES refers to Parallel section refactored: Scipion threads and or "Package compute" lines.", maybe some condition was introduced and the sqlite db gets deadlocked with badly coordinated threads

The issue is reproducible at will for now!

Thank you for your assistance!

[pconesa]

Thanks @yghorbal ! AS far as I know we, at least intentionally didn't introduced any change inthis respect...

But didn't know eitht about that flag. If solves the issue and does not affect anything else it may be a good addition!!

I'll read about it.

[pconesa]

reading docs from sqlite says:

"WAL does not work over a network filesystem"

In Scipion only one host writes others read... mayb is still valid?

@yghorbal , it might be also other change We haven0t change that part for a long time but mayb tomo plugin has change ways of creating sqlites....

We can make this pragmas, optional, adding a variable: JOURNAL_MODE, if present we can add it. Then you can betatest and let us know if that WAL mode actually improves things anf may be better to be de default value?

[yghorbal]

hi @pconesa allo me a couple of days to thoroughly test a full pipeline on multiple combination of versions.
By the way the described issue happened on a local filesystem not networked one. Scipion was executing protocols locally (not on a queue system)

[pconesa]

I see, it does not harm to allow this as an optional behaviour, easier to maintain through config file than editing code, that will be lost after an update.

[yghorbal]

@pconesa I took some time to dig deeper into this issue and I think I found the root cause. As a matter of fact it's not a pyworkflow version issue but rather a python one. In Python 3.11 there was a rework fo the LRU cache of the SQLite module python/cpython#103837 (comment) this led to a change in reference count of various objects like cursors. The direct consequence of this is that SQLite Connection.close() does not release the underlaying file after a Connection.close() in some cases as it used to do with previous Python version. Since the file is not released, once a new connection tries to commit changes, it gets a sqlite3.OperationalError: database is locked reported in this issue.

Based on pyworkflow code I've crafter a small reproducer inspired by pyworkflow code:

scipion-pyworkflow/pyworkflow/mapper/sqlite_db.py

Line 39 in 8a2aa86

class SqliteDb:

The following code will work flawlessly in Python <= 3.10 and will break with a sqlite3.OperationalError: database is locked (after 5s) with Python >= 3.11

from sqlite3 import dbapi2 as sqlite

db = 'tiltseriesM.sqlite'
class bar:
    cons = {}
    def connect(self, db, reuse = False):
        if db not in self.cons or not reuse:
            print('creating a new connection...')
            self.con = sqlite.Connection(db, 5, check_same_thread=False)
            self.cons[db] = self.con
        else:
            print('reusing the old connection...')
            self.con = self.cons[db]
        self.cur = self.con.cursor()
        self.execute = self.cur.execute
        self.executescript = self.cur.executescript
        self.commit = self.con.commit

    def close(self):
        self.cur.close()
        self.con.close()

cursors = []
B = bar()
B.connect(db)
cursors.append(B.cur)
B.execute('select * from Properties;')
B.connect(db, reuse = True)
cursors.append(B.cur)
B.execute('select * from Classes;')
B.close()
B.connect(db)
B.executescript('begin; update Properties set value=1 where key="_size"; commit;')

Here the cursors list mimics keeping references over cursor objects created in the connect method.

I think that the cursor leak comes from this:

scipion-pyworkflow/pyworkflow/mapper/sqlite_db.py

Line 63 in 8a2aa86

self.cursor = self.connection.cursor()

it creates a throw away cursor object each time (even when the connection is reused) and those cursors are never closed.

For now the only viable workaround is to stick with Python 3.10 until this is sorted out.

[pconesa]

Wow! that is a nice finding.!

By default Scipion installs with 3.8 but it is true that you can specify a different version.

We will need some time to tackle 3.11 compatibility. We've found other issues.

I'll leave this open for the moment we address 3.11 compatibility.