Re: Sqlite checkpoint issue

As luck would have it, I've been looking into this very issue over the past=
 few days and can offer some insight.

> On Jun 30, 2020, at 02:13, Venugopal Thotakura <[email protected]> wrote:
>=20
> Hi,
>=20
> We are using sqlite storage engine, we are facing issues with checkpointi=
ng (WAL size going into GB.. It looks like by default checkpointing is disa=
bled, so we enabled auto checkpointing..

Auto-checkpoints should be enabled by default, unless your copy of sqlite w=
as compiled in a strange way. RelStorage does not disable auto-checkpoints,=
 but it will log what the default value is when a connection is opened  (it=
's usually 1000):

DEBUG:relstorage.adapters.sqlite.drivers:Connection: <Connection at 0x11334=
8c30 to '...' in_transaction=3DFalse>.
	Using sqlite3 version: 3.32.3.
	Default    connection settings: {... 'wal_autocheckpoint': 1000,...}
	Changing   connection settings: {'synchronous': 2, 'cache_spill': 483, 'fo=
reign_keys': 0}.
	Desired    connection settings: {'synchronous': 1, 'cache_spill': 0, 'fore=
ign_keys': 1}.
	Unapplied  connection settings: {}.


> <pragmas>
>        wal_autocheckpoint 100
>        wal_checkpoint FULL
> </pragmas>

(The `wal_checkpoint` pragma is a one-time operation, not a persistent sett=
ing that applies to auto-checkpoints. The pragmas are executed when a conne=
ction is opened, so that last line will cause each new connection to run a =
checkpoint. The function-call syntax needed to actually pass `FULL`, e.g., =
`PRAGMA wal_checkpoint(FULL)`, is not supported for the pragmas executed at=
 connection open, though, so the default value of `PASSIVE` gets used inste=
ad. That's probably lucky, because a FULL checkpoint is a blocking operatio=
n and might never successfully complete...)

>=20
> Now, It looks like its trying to do checkpointing, however due to the con=
nections arleady open, it couldn't do that..

Auto-checkpoints are always PASSIVE checkpoints (and never block). PASSIVE =
checkpoints will mark the space in the WAL file that's available for re-use=
, but if there are open *transactions* viewing the database as-of some time=
 in the past, that part of the WAL won't be available for re-use. Depending=
 on the workload, those transactions could be using data at the end of the =
WAL, in which case new uses of the WAL will have to grow the file.

The problem is open transactions, not necessarily open connections.

How do you know if there's an open transaction, and what can you do about c=
ontrolling them?

> So to give overview of our architecture..
>=20
> We connect to db from multiple processes
> - 2 read process (async read with our async connection pool to limit the =
connections)
> - 1 write process (async write)
>=20
>=20
> Here is our async pool.. we prefork the connections (we are seeing someti=
mes db.open is taking longer time to create connections, so we are doing pr=
efork) and use them.


First and most importantly, always use the transaction manager in its expli=
cit mode. There are a number of benefits to that, but most relevant here is=
 that when the transaction manager is in explicit mode, ZODB alters the way=
 it uses RelStorage, and RelStorage is able to manage the underlying databa=
se transaction in a much better way.=20

Second, to be able to use explicit mode (as well as one of the mitigations =
discussed below), I suspect you may need to drop the idea of "pre-forking" =
connections. Let the ZODB DB and its connection pool manage that. (If you'r=
e find it sometimes slow to open connections, you may need to adjust the si=
ze of the ZODB connection pool.) Begin a transaction, open a connection, do=
 the work, then commit/rollback the transaction, and finally close the conn=
ection. By carefully bounding the transaction and connection lifecycle this=
 way, together with using an explicit transaction manager, you can be sure =
about the lifetime of the underlying database transaction as well.

Lastly (and this is not a problem on your side, it's an issue I need to add=
ress in RelStorage) having exactly one concurrent writer actually exacerbat=
es the situation a little bit. That's because of the way connections are in=
ternally handled in RelStorage. Basically, one connection can get in its ow=
n way (again, depending on the workload) and when a commit triggers an auto=
-checkpoint, it may not be able to clean up all the WAL pages. But if anoth=
er connection commits shortly after that and triggers an auto-checkpoint, t=
hen it may be able to make more progress. If there's only ever one writer, =
though, it's likely to keep tripping over its own feet. (This can still hap=
pen with multiple writers but I think it's more rare.)

This is something I will change in RelStorage (I have a prototype fix now).=
 But in the meantime, there are two possible mitigations:=20

1) Use a very low `wal_autocheckpoint` so that connections are cleaning up =
after each other more often. This only matters, of course, if there is more=
 than one writer.
2) Manually invoke a checkpoint *immediately* after committing. This only w=
orks if the transaction managers are in explicit mode, and it has to be imm=
ediately after committing so that the connection is not in its own way. Thi=
s works for a single writer. (And yes, this is using non-public APIs so it'=
s likely to break in the future. Hopefully the changes I make to RelStorage=
 alleviate the issue enough, but if not we can look at doing something more=
 sophisticated and permanent.)


Here's an example program demonstrating this. If the transaction managers a=
re in explicit mode, then the WAL never grows beyond two pages (8K); if the=
y are left implicit, then by the time executing finishes, the WAL has grown=
 to 80MB.


import os
import logging

import transaction
from ZODB.config import databaseFromString

db_config =3D """
%import relstorage
<zodb>
  pool-size 1
  <relstorage>
     keep-history false
     <sqlite3>
        data-dir /tmp/rstest
     </sqlite3>
  </relstorage>
</zodb>
"""

logger =3D logging.getLogger(__name__)

def report_sizes():
    os.system('ls -lh /tmp/rstest')

def run_transaction(db):
    tx =3D transaction.begin()
    conn =3D db.open()
    root =3D conn.root()
    root['key'] =3D 'abcd' * 1000
    tx.commit()
    conn.close()
    checkpoint(conn)

def checkpoint(conn):
    sc =3D conn._storage._load_connection.cursor
    sc.execute('pragma main.wal_checkpoint(passive)')
    sc.fetchall() # Must fetchall! Plus there's actual useful info in the r=
esults.


def main():
    logging.basicConfig(level=3Dlogging.DEBUG)
    logging.getLogger('txn').setLevel(logging.ERROR)
    # Make sure the global (default) transaction manager is
    # explicit.
    transaction.manager.explicit =3D True
    db =3D databaseFromString(db_config)


    # Open an isolated connection. If the transaction
    # manager isn't in explicit mode, it really will talk to
    # the database now, which will cause WAL to start accumulating.
    # Use explicit transaction managers to prevent that from happening
    # and keep a tight reign on transaction duration.
    isolated_txm =3D transaction.TransactionManager()
    isolated_txm.explicit =3D True # If this is commented out, the WAL grow=
s without bound
    c1 =3D db.open(isolated_txm)

    report_sizes()
    for _ in range(10):
        for _ in range(1000):
            run_transaction(db)
        report_sizes()

    c1.close()
    db.close()
    report_sizes()


if __name__ =3D=3D '__main__':
    main()

~Jason

--=20
You received this message because you are subscribed to the Google Groups "=
zodb" group.
To unsubscribe from this group and stop receiving emails from it, send an e=
mail to [email protected].
To view this discussion on the web visit https://groups.google.com/d/msgid/=
zodb/A8BBB6DD-3E0A-4DC4-B683-408F7F21DB43%40nextthought.com.