Hi everybody!
TL;DR:
Shutting down power right after a successfully committed
transaction rolls back that transaction on next startup. This is a
problem in write-on-shutdown-then-power-off scenarios and violates my
expectation of SQLite's transactions being ACID. This can be fixed by
setting the dirSync-flag of the sqlite3OsDelete-call within
pager_end_transaction.
Full:
We are using a slightly patched SQLite 3.7.5 in an embedded system
running under QNX 6.5 as a data store that does the right thing even
when power fails, which has worked remarkably well up to now. After
migrating the database onto a QNX6 filesystem (which does not write
through synchronously) we almost reliably lose the last transaction on
power off, which happens ~1.5s after. We use journal mode, BTW, for its
more reliably limited file sizes.
While 3.7.5 is quite old, the same behaviour can easily be demonstrated
with a simple test program using sqlite-amalgamation-201601141433. To
try yourself, unpack sqlite3.{c,h} into the same directory as the
attached files and run make.
The test program opens a database in the current directory, creates a
table and adds a row to it, then asks you to power off. I did this on
our device, running the snoopy filesystem access logger alongside to see
what's happening:
> # ls -l
> total 16
> drwxr-xr-x 2 root root 4096 Jan 01 00:02 .
> drwxrwxr-x 4 root root 4096 Jan 01 00:02 ..
> # /fs/sda0/snoopy `pwd`
> # /fs/sda0/uncommit
> opening uncommit.sqlite...
> 4382854,1,,READLINK,/mnt/boardbook/test/uncommit.sqlite,No such file or
> directory
> 4382854,1,,OPEN,/mnt/boardbook/test/.,No error,
> 4382854,1,,CLOSE,/mnt/boardbook/test/.,No error
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No such file or directory,
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,rwc
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 4382854,1,,DEVCTL,/mnt/boardbook/test/uncommit.sqlite,No
> error,40a8020d,FSYS_STATVFS
> 4382854,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,0
> 4382854,1,,READ,/mnt/boardbook/test/uncommit.sqlite,No error,0/100
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No such file or
> directory,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-wal,No such file or
> directory
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No such file or
> directory,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-wal,No such file or
> directory
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No error,rwc
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite-journal,No error,file
> 4382854,1,,CHOWN,/mnt/boardbook/test/uncommit.sqlite-journal,No error,0:0
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite-journal,No error,file
> 4382854,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite-journal,No error,0
> 4382854,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite-journal,No error,512/512
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,0
> 4382854,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite,No error,1024/1024
> 4382854,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,1024
> 4382854,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite,No error,1024/1024
> 4382854,1,,FSYNC,/mnt/boardbook/test/uncommit.sqlite,No error
> 4382854,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite-journal,No error
> 4382854,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-journal,No error
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 4382854,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 4382854,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 4382854,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> POWER OFF NOW!
Directly afterwards I yanked the cable. After reboot:
> # ls -l
> total 21
> drwxr-xr-x 2 root root 4096 Jan 01 00:04 .
> drwxrwxr-x 4 root root 4096 Jan 01 00:02 ..
> -rw-r--r-- 1 root root 2048 Jan 01 00:04 uncommit.sqlite
> -rw-r--r-- 1 root root 512 Jan 01 00:04
> uncommit.sqlite-journal
The journal file is still there despite having been successfully
unlinked 9 lines before ?POWER OFF NOW!? above. Which is not surprising,
given that the directory has not been synced in any way.
I did the same thing with a patched SQLite, changing one line in
pager_end_transaction() from
rc = sqlite3OsDelete(pPager->pVfs, pPager->zJournal, 0);
to
rc = sqlite3OsDelete(pPager->pVfs, pPager->zJournal, 1);
> # rm *
> # /fs/sda0/snoopy `pwd`
> # /fs/sda0/uncommit-patched
> opening uncommit.sqlite...
> 3252313,1,,READLINK,/mnt/boardbook/test/uncommit.sqlite,No such file or
> directory
> 3252313,1,,OPEN,/mnt/boardbook/test/.,No error,
> 3252313,1,,CLOSE,/mnt/boardbook/test/.,No error
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No such file or directory,
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,rwc
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 3252313,1,,DEVCTL,/mnt/boardbook/test/uncommit.sqlite,No
> error,40a8020d,FSYS_STATVFS
> 3252313,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,0
> 3252313,1,,READ,/mnt/boardbook/test/uncommit.sqlite,No error,0/100
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No such file or
> directory,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-wal,No such file or
> directory
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No such file or
> directory,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-wal,No such file or
> directory
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite-journal,No error,rwc
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite-journal,No error,file
> 3252313,1,,CHOWN,/mnt/boardbook/test/uncommit.sqlite-journal,No error,0:0
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite-journal,No error,file
> 3252313,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite-journal,No error,0
> 3252313,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite-journal,No error,512/512
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,0
> 3252313,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite,No error,1024/1024
> 3252313,1,,LSEEK,/mnt/boardbook/test/uncommit.sqlite,No error,1024
> 3252313,1,,WRITE,/mnt/boardbook/test/uncommit.sqlite,No error,1024/1024
> 3252313,1,,FSYNC,/mnt/boardbook/test/uncommit.sqlite,No error
> 3252313,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite-journal,No error
> 3252313,1,,UNLINK,/mnt/boardbook/test/uncommit.sqlite-journal,No error
> 3252313,1,,OPEN,/mnt/boardbook/test,No error,r
> 3252313,1,,FSYNC,/mnt/boardbook/test,No error
> 3252313,1,,CLOSE,/mnt/boardbook/test,No error
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,LOCK,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,OPEN,/mnt/boardbook/test/uncommit.sqlite,No error,
> 3252313,1,,STAT,/mnt/boardbook/test/uncommit.sqlite,No error,file
> 3252313,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> 3252313,1,,CLOSE,/mnt/boardbook/test/uncommit.sqlite,No error
> POWER OFF NOW!
Yank, reboot,
> # ls -l
> total 20
> drwxr-xr-x 2 root root 4096 Jan 01 00:01 .
> drwxrwxr-x 4 root root 4096 Jan 01 00:02 ..
> -rw-r--r-- 1 root root 2048 Jan 01 00:01 uncommit.sqlite
No zombie journal file this time, as expected, as unlinking the journal
is followed by fsyncing the directory. The same patch also fixes our
original problem.
I found some old email exchange about seemingly the same topic (see
http://sqlite.1065341.n5.nabble.com/Journal-deletion-no-directory-fsync-td37700.html),
but no conclusion. Therefore I'm not sure whether this is a genuine bug
or merely a tradeoff ?it's more efficient that way and when power fails
a slight bit earlier the transaction is interrupted anyway?.
Please consider adding the fix to the code, at least as -D option.
SQLite journal mode doesn't guarantee durability otherwise.
S.M.
--
Dipl.-Phys. (Univ) Stefan Meinlschmidt, Senior Software Engineer
Am Wolfsmantel 46, 91058 Tennenlohe, Germany
Tel: +49-8458-3332-531 stefan.meinlschmidt at esolutions.de
Fax: +49-8458-3332-20-531
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: Makefile
URL:
<http://mailinglists.sqlite.org/cgi-bin/mailman/private/sqlite-users/attachments/20160119/defdfb22/attachment.ksh>
