Increasing "database is locked" errors during update

[lemon24]

Starting with 2020-04-15, there has been an increasing number of "database is locked" errors during update on my reader deployment (update every hour and update --new-only && search update every minute).

Most errors happen at XX:01:0X, which I think indicates the hourly and minutely updates are clashing. It's likely that search update is hogging the database (since we know it has long-running transactions).

I didn't see any metric changes on the host around -04-15.

Logs.

$ head -n1 /var/log/reader/update.log | cut -dT -f1
2019-07-26
$ cat locked.py 
import sys

last_ts = None

for line in sys.stdin:
    if line.startswith('2020-'):
        last_ts, *_ = line.partition(' ')
    if line.startswith('reader.exceptions.StorageError: sqlite3 error: database is locked'):
        print(last_ts)

$ cat /var/log/reader/update.log | python3 locked.py | cut -dT -f1 | uniq -c
      1 2020-04-15
      4 2020-04-16
      3 2020-04-17
      6 2020-04-18
      2 2020-04-19
      1 2020-04-20
      2 2020-04-21
      3 2020-04-22
      3 2020-04-23
      2 2020-04-24
      3 2020-04-25
      1 2020-04-26
      4 2020-04-27
      2 2020-04-28
      3 2020-04-30
      6 2020-05-01
      8 2020-05-02
     12 2020-05-03
      6 2020-05-04
      4 2020-05-05
      5 2020-05-06
      1 2020-05-07
      2 2020-05-08
      3 2020-05-09
      4 2020-05-10
      4 2020-05-11
      7 2020-05-12
      8 2020-05-13
      9 2020-05-14
      6 2020-05-15
      5 2020-05-16
      9 2020-05-17
     16 2020-05-18
      9 2020-05-19
     10 2020-05-20
     15 2020-05-21
     23 2020-05-22
     20 2020-05-23
     19 2020-05-24
     22 2020-05-25
     22 2020-05-26
     21 2020-05-27
     15 2020-05-28
     18 2020-05-29
     14 2020-05-30
     11 2020-05-31
     17 2020-06-01
     13 2020-06-02
     18 2020-06-03
     10 2020-06-04
     15 2020-06-05
     10 2020-06-06
     14 2020-06-07
     15 2020-06-08
     18 2020-06-09
     17 2020-06-10
     19 2020-06-11
     21 2020-06-12
     19 2020-06-13
     16 2020-06-14
     13 2020-06-15
     24 2020-06-16
     24 2020-06-17
     24 2020-06-18
     24 2020-06-19
     24 2020-06-20
     24 2020-06-21
     24 2020-06-22
     24 2020-06-23
     24 2020-06-24
     11 2020-06-25
$ cat /var/log/reader/update.log | python3 locked.py | cut -dT -f2 | cut -d: -f2- | cut -c1-4 | sort | uniq -c | sort -rn | head
    510 01:0
    119 03:0
     76 01:1
     46 01:2
     30 00:5
     14 00:3
     13 00:0
      7 01:3
      7 00:4
      3 05:0

I should check if there was a trigger that started this, or if the number of entries/feeds simply hit some threshold.

Also it, would be nice to show the pid in the logs so I can see which of the commands is failing, and maybe intercepting the exception and showing some nicer error message.

Things that are likely to improve this:

• [helps] Enabling WAL (Use WAL by default #169).
• Using --workers 20 to give the hourly update a chance to finish before the second minute of the hour. Obviously, this isn't actually addressing the problem.
• Increasing the timeout passed to sqlite3.connect (at the moment we're using the 5s default).
• [doesn't help] Using a SQLite with HAVE_USLEEP (but this is not necessarily a reader issue; we could document it, though).
• Adding retrying in reader. ಠ_ಠ, SQLite already has it built in, it's sucky because of the HAVE_USLEEP thing.
• Wrap the whole update with a lock. ಠ_ಠ, idem.
• Make the search update chunks more spaced out, to allow other stuff to happen.
• Make search update not hog the database by not stripping HTML inside the transaction.

[lemon24]

I enabled WAL on my database manually at around 2020-06-25T11:34 UTC.

Update: So, yeah, it definitely worked, but not all the way.

$ date
Mon Jun 29 21:11:02 UTC 2020
$ cat /var/log/reader/update.log | grep ^20 | cut -dT -f1 | uniq -c | tail -
   1649 2020-06-20
   1969 2020-06-21
   1896 2020-06-22
   2384 2020-06-23
   1963 2020-06-24
   2976 2020-06-25
   3451 2020-06-26
   3464 2020-06-27
   3372 2020-06-28
   3208 2020-06-29
$ cat /var/log/reader/update.log | python3 locked.py | cut -dT -f1 | uniq -c | tail 
     24 2020-06-20
     24 2020-06-21
     24 2020-06-22
     24 2020-06-23
     24 2020-06-24
     14 2020-06-25
      1 2020-06-26
      1 2020-06-27
      5 2020-06-28
      3 2020-06-29

[lemon24]

A few notes:

The logs above show that some days the hourly update was never finishing; I started looking into this because explainxkcd.com entries were appearing way earlier than the xkcd.com ones (when updating, feeds are sorted in alphabetical order).

This shows that feed.last_updated/.last_exception (#68) don't have enough info to show in the web app that reader itself doesn't work. We could have a global equivalent, but I don't think its the right place to solve this: feed.last_exception contains exceptions reader can't do anything about, a global last_exception would contain bug in reader (update_feeds() should never fail, from the point of view of the web application user). Also, how are you going to set it if you can't write to the database?

If it becomes a habit that update fails midway, we could update the feeds with lowest last_updated first (so all feeds get eventually updated). Needless to say, this is also not the right thing to fix.

[lemon24]

OK, so I think I using HAVE_USLEEP either doesn't help, or it was already enabled (it doesn't always show up in PRAGMA compile_options output, see lemon24/smalltsdb#2 (comment) / beetbox/beets#2241).

I used this script to run the update commands like cron would, but at a scaled down timeframe; for all 4 combinations of journal mode delete/WAL and system SQLite / custom HAVE_USLEEP build, the hourly update fails during the second minutely update (which is what we see for real).

[lemon24]

So yeah, we should probably do HTML stripping outside of the transaction. Note how the strip_html() cumulative time makes up most of the sqlite3.Connection.execute() one:

$ python scripts/bench.py profile update_search
update_search num_entries=2048

         3387121 function calls (3383024 primitive calls) in 2.967 seconds

   Ordered by: cumulative time
   List reduced from 206 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.967    2.967 bench.py:297(time_update_search)
        3    0.000    0.000    2.967    0.989 contextlib.py:71(inner)
        1    0.000    0.000    2.958    2.958 core.py:726(update_search)
        1    0.000    0.000    2.958    2.958 _search.py:291(update)
        1    0.000    0.000    2.958    2.958 _search.py:300(_update)
        1    0.091    0.091    2.957    2.957 _search.py:406(_insert_into_search)
       37    0.228    0.006    2.876    0.078 {method 'execute' of 'sqlite3.Connection' objects}
     4097    0.024    0.000    2.648    0.001 _search.py:75(strip_html)
     4097    0.097    0.000    1.560    0.000 __init__.py:97(__init__)
     4097    0.009    0.000    1.272    0.000 __init__.py:402(_feed)
     4097    0.353    0.000    1.258    0.000 _lxml.py:320(feed)
     4097    0.010    0.000    1.017    0.000 element.py:1801(select)
     4097    0.007    0.000    1.001    0.000 __init__.py:95(select)
     4097    0.007    0.000    0.845    0.000 css_match.py:1473(select)
     4097    0.010    0.000    0.839    0.000 css_match.py:1478(iselect)
     4097    0.011    0.000    0.770    0.000 css_match.py:1383(select)
    12291    0.015    0.000    0.707    0.000 css_match.py:1414(match)
    12291    0.043    0.000    0.677    0.000 css_match.py:1299(match_selectors)
    49164    0.040    0.000    0.617    0.000 css_match.py:690(match_tag)
    12291    0.080    0.000    0.439    0.000 _lxml.py:213(start)

[lemon24]

Ok, we could do this to take strip_html() out of transactions:

• pull a bunch of entry content into Python,
• strip HTML outside of a transaction, and then
• update each entry only if its last_updated didn't change.

Currently, Search._insert_into_search() does this (pseudocode):

# everything under "with sql" is a single SQL statement 

while True:
    with transaction:
        # write lock
        with sql:
            input = get_entries_to_update(chunk_size or -1)
            # this takes most of the time
            stripped_entries = strip_entries(get_unstripped_entries(input))
            insert_into_search(
                part 
                for entry in stripped_entries 
                for part in entry.parts
            )

        if sql.rowcount == 0:
            # nothing to update, bail early
            break

        with sql:
            # input is identical to the previous one,
            # since we're in a transaction
            input = get_entries_to_update(limit)
            set_to_update_flag(input, 0)

        if not chunk_size:
            # the first iteration did everything, bail
            break

        if sql.rowcount < chunk_size:
            # this is the last chunk, bail
            break

We could instead do this:

while True:
    with transaction:
        # read lock
        with sql:
            input = get_entries_to_update(chunk_size)
            unstripped_entries = get_unstripped_entries(input)

    if not unstripped_entries:
        # nothing to update
        break

    # this takes most of the time
    stripped_entries = strip_entries(unstripped_entries)

    for stripped_entry in stripped_entries:

        with transaction:
            # explicitly acquire a write lock

            # update: this check added after the initial implementation
            if not current_entry.to_update:
                #  a concurrent call updated this entry, skip it
                continue

            with sql: 
                insert_into_search(
                    part 
                    for part in stripped_entry.parts
                    if current_entry.last_updated == stripped_entry.last_updated
                )

            # presumably we could have inserted the whole chunk,
            # but we'd have to throw everything away if just one entry changed

            if sql.rowcount != len(stripped_entry.parts):
                # entry changed since we got it, skip it, 
                # we'll catch it on the next loop
                rollback
                continue

            with sql:
                set_to_update_flag(stripped_entry, 0)

[lemon24]

OK, after 82234aa:

The script I used above still fails when using 5/8 seconds as timeout (the "scaled down" one), but does not fail anymore when using the default 5 seconds one (it did before the change).

We see a 1.7x increase in the update_search() timings when updating >64 entries:

$ python scripts/bench.py diff before.txt after.txt --format times
number num_entries update_search
     4          32          2.15
     4          64          1.56
     4         128          1.58
     4         256          1.57
     4         512          1.64
     4        1024          1.67
     4        2048          1.66

The profile shows the cumulative time of sqlite3.Connection.execute(many) decreased from 2.8s to .6s, but increased from .2s when not accounting for the time spent in strip_html(); however, this time is now spread over 2k calls (as opposed to ~40 before).

The current implementation starts a transaction for each of the 2k calls; we could probably batch the inserts somewhat, at the expense having to retry the whole batch if a single entry in it got updated since we started work on this batch. At the moment, this seems overkill.

$ python scripts/bench.py profile update_search
update_search num_entries=2048
...
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   ...
        1    0.871    0.871    4.394    4.394 _search.py:409(_insert_into_search)
     4097    0.024    0.000    2.793    0.001 _search.py:77(strip_html)
     4097    0.101    0.000    1.670    0.000 __init__.py:97(__init__)
   ...
     2048    0.663    0.000    0.675    0.000 {method 'executemany' of 'sqlite3.Connection' 

[lemon24]

I deployed the change above at about 2020-07-03T13:34 UTC.

Update: The CPU utilization on the instance went to 90% ...

Timeline:

• 13:34 - Change deployed.
• 14:00 - update starts and finishes successfully after 1 minute 35 seconds
• 14:00 - CPU utilization goes to ~90% and stays there (background utilization is ~1%).
• 15:00 - update starts and fails with "database is locked" after updating 2 feeds
• 15:20 - CPU utilization decreases to about 5%.
• 15:50 - Change rolled back.

There's nothing in the logs about search update, this is something we should fix (the CLI should at least say " starting / ending" or something).

Update #2: As expected, there was an infinite loop. It was because after the fancy insert into entries_search ... where entries.last_updated = :_last_updated, cursor.rowcount was 0 for some reason (despite the last_updateds matching). I pulled out the last_updated check into Python (with an additional select), and made the insert a simple one.

[lemon24]

OK, so the number of errors kept increasing.

Looking at some backups, I noticed the following:

• This morning, the search updates would have nothing to update, but even so, over 3 minutes would pass from the start of the command until the _delete_from_search (there isn't more detailed logging, but this points to that query taking that long).
• A few hours later (presumably after a feed got some updates), the _delete_from_search log line would report >2k rows being deleted for a single 256-entry chunk.
• Somewhere between June 23rd and 30th, some entries started having more than 3 rows in entries_search (no entry has more than 2 contents and a summary); the maximum for the 23rd was 9 rows, and one for the 30th was 27 rows. The top entries were all from the same feed, with exactly the same number of rows.

Some conclusions:

• There's a bug where two search updates running in parallel can result in entries_search rows getting duplicated. It was there before this issue was opened. It's likely the more duplicates there are, the longer the update takes, increasing the chance two minutely updated overlap.
• The naive "after update on feeds" trigger that marks entries as to be updated when a feed changes is too naive: a feed changing in any way results in all its entries needing to be updated, and currently feeds' last_updated changes if they get a 304 Not Modified or if there's any new entry.

Update: This gist has a script that reproduces the issue and output showing what's happening.

Update #2: The scenario is:

• entry has to_update set
• _delete_from_search removes it from search
• loop 1 of _insert_into_search finds entry and inserts it into search, clears to_update
• entry has to_update set (if to_update is set because the feed changed, last_updated does not change; even if it did, it doesn't matter, since the transaction only spans a single loop)
• loop 2 of _insert_into_search finds entry and inserts it into search again, clears to_update
• loop 3 of _insert_into_search doesn't find any entry, returns

[lemon24]

I deployed the change above at about 2020-07-07T20:15 UTC and re-enabled the update search minutely job, after running search disable/enable/update to make sure the index was generated correctly.

Update: Still seeing "database is locked", but at least I didn't see any duplicate entries_search rows.

[lemon24]

This gist has a summary of timings for each db.execute(many) call from the updates between roughly --07-08T19/--07-09T07.

Some observations:

• DELETE FROM entries_search (the FTS5 table) seems to take a lot, both when deleting many rows (_delete_from_search; 700 calls, 8s max, 2.7s p95) and when deleting a few (_insert_into_search_one_chunk).
  • Inserts take way less (1000x less both on average and at p99).
• The naive "after update on feeds" trigger mentioned above) causes a huge amount of churn (as expected); over 12 hours, 18k entries were inserted into entries_search (for reference, there are 10k entries total, only 9 entries were added/updated, and only 2 updates ran to completion).

Next steps:

• "after update on feeds" trigger.
• Make the _delete_from_search DELETE FROM entries_search chunk size smaller.
• Maybe find a way to make the entries_search deletes faster.
  • We can't create an index on entries_search because it's a virtual table.
  • create index esif on entries_search_content (c3, c4); (one of the shadow tables) doesn't seem to help.
  • Maybe we can get rid of the JOIN entries_seach in the query; it results in a second table scan on entries_search.

[lemon24]

Deployed the smaller _delete_from_search chunk size change at about --07-10T16:30. (Today things got a little better by themselves too, only 13/16 updates failed.)

Update: That doesn't seem to have helped much, we got roughly the same:

• amount of failures (11/16 for hourly updates and 3 failures for update search)
• timings for _delete_from_search (all stats pretty much the same)

[lemon24]

I deployed the change above at --07-11T09:25. It should almost halve the _delete_from_search query time.

BTW, I'm leaving the "after update on feeds" trigger fix for last because it's a sure win, and it'll make it harder to measure the impact of the other changes.

Update: 2/6 failures for hourly updates; the _delete_from_search query time is a bit lower, but not by much – maybe the query planner optimized the second scan away? (despite it showing up in the explain query plan output)

[lemon24]

I deployed the change above at --07-11T15:43.

Update: As of --07-11T20:26: 0/5 hourly updates failed, and there was exactly 1 insert into entries_search – because 1 entry was updated (previously, there were 1-1.5k inserts per hour on average).

Update: As of --07-12T08:25: Still no failed update. Also:

[lemon24]

To summarize what happened:

• I started seeing increasing "database is locked" errors during update.
• I enabled WAL, it helped a bit.
• I tried to find a way to replicate the errors seen in prod, but couldn't; I could get it to fail all the time, but that wasn't that useful.
• I tried to see if using a SQLite compiled with HAVE_USLEEP helps. It didn't, most likely because the stock SQLite already has it. Measuring query execution time here would have shown clearly queries are not failing after roughly 1, 2, 4, ..., $busy_timeout seconds (expected when HAVE_USLEEP is missing).
• I moved strip_html() calls outside of transactions; I don't know if it helped (it most likely did; this was the "obvious" fix). During this:
  • I found a bug where two search updates running in parallel can result in entries_search rows getting duplicated.
    • I replicated this bug by running a bunch of update_feeds() and update_search() calls in a loop in a bunch of threads on a database with a few entries that kept being updated.
  • I noticed the naive "after update on feeds" trigger was too naive, and would update all entries of a feed whenever last_updated changed; this resulted in 1-1.5k entries being reindexed per hour on average, even if no entry would actually change. Measuring query execution time would have made this obvious.
• I fixed the duplicate entries_search rows bug.
• I added the --debug-storage option to log query execution time, and wrote a little summarizer script. This:
  • Showed that DELETE FROM entries_search (the FTS5 table) in _delete_from_search took way more than expected, even when no entries were to be deleted (2.7s at p95).
  • Put a number on the churn caused by the naive "after update on feeds" trigger.
• I made the _delete_from_search DELETE FROM entries_search chunk size smaller. It was an expected low hanging fruit, but didn't help at all (and may actually hurt when there's a lot of stuff to delete), most likely because each query does a full entries_search scan.
• I removed a needless JOIN from the _delete_from_search DELETE FROM entries_search query. This also didn't help, likely because the query planner already optimized a second scan away, despite it showing up in the explain query plan output.
• I fixed the naive "after update on X" triggers. As expected, this had a dramatic positive impact (no update failures after this).
  • I noticed that the "after update on entries" trigger never fires, because we're using INSERT OR REPLACE to update entries (which is equivalent to DELETE + INSERT, not UPDATE).

Lessons learned:

• A little bit of measurement goes a long way.
• Prefer measuring before fixing, maybe even before the "obvious" fix.
  • Measure individual queries, then "explain query plan" on top talkers seems like a good approach for doing storage improvements going forward.
• Measure in prod.
  • I got very different results for DELETE FROM entries_search on my laptop vs. the "prod" instance; _delete_from_search didn't show up at all in the profiling done on the laptop. This may be due to SSD/EBS differences, or different SQLite versions (3.28 vs 3.22).
• FTS5 tables are slow for non-FTS queries, and you can't create indexes for virtual tables.
• Some naive approaches are too naive.
  • Re: "after update on feeds" triggers; I don't think I made the wrong decision when not optimizing stuff when I implemented the search initially, but I did underestimate the impact that would have.
• It's hard to reason about concurrency issues when doing things outside transactions. Assumptions that hold for sequential runs fail quickly for parallel ones.
  • Even for simple operations, it's hard to think of "what might fail" analytically.
  • Running a bunch of calls in a bunch of threads as fast as possible is a good way of finding some concurrency issues.
    • Maybe we should have a consistency test like this.
• A config file to enable / disable --debug-search -vv globally would be nice.
  • Doing it by changing crontab entries with Ansible was more of a pain than it should have been.
• It's hard to test some optimizations in prod.
  • E.g.: I still don't know if deleting search rows in smaller chunks helped at all.
  • Feature flags (maybe in a config file) may help with this (or it may be overkill).

[lemon24]

It started again today...

$ cat /var/log/reader/update.log | python3 locked.py | cut -d: -f1 | uniq -c | tail -n60
      3 2020-07-13T09
     27 2020-07-13T10
     28 2020-07-13T11
     19 2020-07-13T12
$ cat /var/log/reader/update.log | grep -c 'StorageError: sqlite3 error: database is locked'
3
$ cat /var/log/reader/update.log | grep -c 'SearchError: sqlite3 error: database is locked'
74

Meanwhile, the web app is very slow (/reader/?limit=64 loads in 24s as opposed to 0.2s).

---

--debug-storage output shows stuff like:

_search.py _delete_from_search
DELETE FROM entries_search WHERE (_id, ...
<no exception>
    n      38.0000
    avg    89.7980
    min    52.8673
    p50    93.1768
    p90   111.4728
    p95   116.9746
    p99   123.2010
    max   124.0840

_search.py _delete_from_sync_state
DELETE FROM entries_search_sync_state WHERE (id, ...
<no exception>
    n      38.0000
    avg     1.6535
    min     0.0009
    p50     2.4091
    p90     2.5591
    p95     2.7303
    p99     4.0841
    max     4.8089

---

The burst balance started decreasing at --07-12T08:15, but I can't figure out why (I made no change around that time).

---

Rebooted at --07-13T14:00.

Update: ... and didn't happen again after that.