OperationalError: database is locked

[admin]

A lot of OperationalError: database is locked errors happen during saving of the session changes, after the request is processed and before the output is sent.

Typical traceback:

Traceback #most recent call last#:
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/main.py", line 435, in _dispatch_request
    dispatcher.dispatch#req#
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/main.py", line 230, in dispatch
    req.session.save##
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/session.py", line 97, in save
    #self.sid,##
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/util.py", line 50, in execute
    return self.cursor.execute#sql_escape_percent#sql#, args#
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/sqlite_backend.py", line 58, in execute
    args or [])
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/sqlite_backend.py", line 50, in _rollback_on_error
    return function#self, *args, **kwargs#
OperationalError: database is locked

We should do better here than raising an internal error in this case, see comment:2.

[Emmanuel Blot]

See MostFrequentDuplicates (database is locked) + PluginIssue (Agilo plugin)

[Christian Boos]

I noticed that a good fraction of the recently reported tracebacks for the database is locked issue show that session.save() in dispatch to be the failing call.

But this failure is not a "critical" one, in the sense that it happens very late in the processing of a request, an eventual POST would already have succeeded and showing an internal error here is then somewhat misleading. So I think we could eventually catch this error and show it as a warning instead of an internal error.

For this, we need to save the session before calling render_template, which means that any session change happening during this rendering will not be taken into account.

Here's the patch:

trac/web/main.py

@@ -50 +50 @@
 from trac.util.text import exception_to_unicode, shorten_line, to_unicode
 from trac.util.translation import tag_, _
 from trac.web.api import *
-from trac.web.chrome import Chrome
+from trac.web.chrome import Chrome, add_warning
 from trac.web.clearsilver import HDFWrapper
 from trac.web.href import Href
 from trac.web.session import Session
@@ -220 +220 @@
                     else: # Genshi
                         template, data, content_type = \
                                   self._post_process_request(req, *resp)
+                        try:
+                            # Give the session a chance to persist changes
+                            req.session.save()
+                        except Exception, e: # TracDatabaseError (#6348)
+                            add_warning(
+                                req, _("Changes to user session couldn't be "
+                                       "saved (%(err)s)",
+                                       err=exception_to_unicode(e)))
                         if 'hdfdump' in req.args:
                             req.perm.require('TRAC_ADMIN')
                             # debugging helper - no need to render first
@@ -231 +239 @@
                             output = chrome.render_template(req, template,
                                                             data,
                                                             content_type)
-                            # Give the session a chance to persist changes
-                            req.session.save()
                             req.send(output, content_type or 'text/html')
                 else:
                     self._post_process_request(req)

I don't think anything in Trac changes the session during rendering, but if some plugins do, it remains to be seen if they really have to or if they could do this earlier.

[osimons]

I'm poking into this as part of ​bitten:ticket:269, and my regular development setup with some 20-25 active tabs is a consistent test-bed for Database is locked errors. I can have 25 Bitten tabs and 'Reload All Tabs' without issues. Add two tabs with Timeline, and things starting to lock up consistently. Here is what I find:

• My own Bitten-contained patches on the mentioned ticket helps a little, but is no solution.
• It does not matter what I select to render in the Timeline - it locks regardless of how many filters or what filters are selected.
• Your patch actually seems to help in that it makes all Bitten tabs render OK quite consistently, containing the locking error to the two Timeline tabs that still more or less always fails (sometimes with warning, sometimes never quite getting that far). And, as you correctly state: More or less always involving req.session.save().

So, either there is something fundamentally wrong with the Timeline, or the Timeline shows a symptom of something holding on to the db that then shows up when Timeline needs to save. That said, i don't understand why the session should try to save when nothing has changed in my session data for a simple reload? Is something flawed with Session? I haven't looked at the session code for a long time, but really we should store the _old_data on the session too and just check the object to see if it has been updated - without hitting the database.

The problem of templates not being able to store session data is fine by me - nothing in templates should have a need for persistence in my opinion.

/me really wanted to reschedule for 0.11.6, and tried hard to leave it alone for now… (patch more or less identical)

[Christian Boos]

Replying to osimons:

I'm poking into this as part of ​bitten:ticket:269,

Thanks for testing! I added some comments to that ticket as well.

Add two tabs with Timeline, and things starting to lock up consistently.

Yes, the timeline pages seem to be good triggers, if you have lots of events. What is especially a performance killer is the [timeline] changeset_show_files = location setting, due to the get_changes() done for each changeset (#6654 will help).

But I also need some pages modifying the session to the mix, otherwise it's no problem for me.

So, either there is something fundamentally wrong with the Timeline, or the Timeline shows a symptom of something holding on to the db that then shows up when Timeline needs to save.

The timeline queries probably hold a read lock for far too long , yes. We could "fix" that at the level of each timeline provider, or globally (i.e. what #3446 is about). I'd prefer globally, because:

• the iteration/yield might still be a superior solution for DB backends with better concurrency
• all the providers would be "fixed" at once; leaving one provider in one plugin do the wrong thing and you have essentially no benefit from fixing the others
• we could have a [trac] trade_memory_for_speed setting which could be used to make this feature optional

That said, i don't understand why the session should try to save when nothing has changed in my session data for a simple reload? Is something flawed with Session? I haven't looked at the session code for a long time, but really we should store the _old_data on the session too and just check the object to see if it has been updated - without hitting the database.

This is what should happen. But if you have timeline pages with different sets of providers or different daysback values, then you'll get session modifications.

The problem of templates not being able to store session data is fine by me - nothing in templates should have a need for persistence in my opinion.

/me really wanted to reschedule for 0.11.6, and tried hard to leave it alone for now… (patch more or less identical)

If no one has a concern about this change of behavior (which might impact Macros for example), then I'd be OK with that.

On a related note, I've been pondering whether to do all the remaining DB layer fixes on 0.11.6 first or on trunk first (and then eventually backport). What do you think?