“SQLite database is busy” : contention on the store database
(address . bug-guix@gnu.org)
877dvz7228.fsf@gnu.org
Hi,
On berlin.guix.gnu.org, we’ve seen a lot of contention on the store
database for a month or so, with messages like:
warning: SQLite database is busy
More often than not, everything slows down to a halt, and builds don’t
proceed.
We initially discussed it here:
When that happens we typically see 30+ processes that have opened the
database:
Toggle snippet (37 lines)
ludo@berlin ~$ sudo fuser -v /var/guix/db/db.sqlite-shm
USER PID ACCESS COMMAND
/var/guix/db/db.sqlite-shm:
root 1211 F...m guix offload
root 1845 F...m guix-daemon
root 6070 F...m guix-daemon
root 31378 F...m guix-daemon
root 31380 F...m guix-daemon
root 47381 F...m guix-daemon
root 47382 F...m guix-daemon
root 47383 F...m guix-daemon
root 47385 F...m guix-daemon
root 47681 F...m guix-daemon
root 48506 F...m guix offload
root 48542 F...m guix offload
root 49417 F...m guix-daemon
root 49472 F...m guix-daemon
root 49971 F...m guix-daemon
root 50027 F...m guix-daemon
root 50847 F...m guix offload
root 54625 F...m guix-daemon
root 54723 F...m guix-daemon
root 55470 F...m guix-daemon
root 55614 F...m guix-daemon
root 55617 F...m guix-daemon
root 56225 F...m guix-daemon
root 57732 F...m guix-daemon
root 57733 F...m guix-daemon
root 57738 F...m guix-daemon
root 57739 F...m guix-daemon
root 57740 F...m guix-daemon
root 58772 F...m guix-daemon
root 59056 F...m guix-daemon
root 99055 F...m guix-daemon
root 127690 F...m guix offload
In this case, the first process seems to be in the deduplication phase
in ‘finalize-store-file’:
Toggle snippet (16 lines)
ludo@berlin ~$ sudo strace -p 1211
strace: Process 1211 attached
utimensat(AT_FDCWD, "/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter", [{tv_sec=1592814617, tv_nsec=396083395} /* 2020-06-22T10:30:17.396083395+0200 */, {tv_sec=1, tv_nsec=0} /* 1970-01-01T01:00:01+0100 */], 0) = 0
chmod("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter", 040555) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=1306, tv_usec=334062}, ru_stime={tv_sec=143, tv_usec=819675}, ...}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=1450, tv_nsec=153748295}) = 0
lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter/xt_connlimit.ko", {st_mode=S_IFLNK|0777, st_size=125, ...}) = 0
readlink("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter/xt_connlimit.ko", "/gnu/store/x8d1hmv17jawp4a7nwwb4"..., 100) = 100
readlink("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter/xt_connlimit.ko", "/gnu/store/x8d1hmv17jawp4a7nwwb4"..., 200) = 125
mkdir("/gnu", 0777) = -1 EEXIST (File exists)
mkdir("/gnu/store", 0777) = -1 EEXIST (File exists)
mkdir("/gnu/store/.links", 0777) = -1 EEXIST (File exists)
lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter/xt_connlimit.ko", {st_mode=S_IFLNK|0777, st_size=125, ...}) = 0
stat("/gnu/store/.links/05p6zpj56f00g07c3621747kz3bjc6zbr8bgg8xysdajq18qgvlv", {st_mode=S_IFREG|0444, st_size=6880, ...}) = 0
At that point it has the database opened 3 times: once from
‘with-temporary-store-file’, once ‘with-database’ in
‘finalize-store-file’, and once from ‘register-items’ in
‘finalize-store-file’. Commit d7fb5538013710288e91657499f0e04207115776
removed the last one.
Toggle snippet (27 lines)
ludo@berlin ~$ sudo ls -l /proc/1211/fd
total 0
lr-x------ 1 root root 64 Jun 22 11:49 0 -> 'pipe:[10239344]'
l-wx------ 1 root root 64 Jun 22 11:49 1 -> 'pipe:[10239343]'
lr-x------ 1 root root 64 Jun 22 11:49 10 -> 'pipe:[10129708]'
l-wx------ 1 root root 64 Jun 22 11:49 11 -> 'pipe:[10129708]'
lr-x------ 1 root root 64 Jun 22 11:49 12 -> 'pipe:[10214031]'
l-wx------ 1 root root 64 Jun 22 11:49 13 -> 'pipe:[10214031]'
l-wx------ 1 root root 64 Jun 22 11:49 14 -> /var/guix/offload/141.80.167.168:22/1
lrwx------ 1 root root 64 Jun 22 11:49 15 -> 'socket:[8056368]'
lrwx------ 1 root root 64 Jun 22 11:49 16 -> 'socket:[10433466]'
lrwx------ 1 root root 64 Jun 22 11:49 17 -> /var/guix/db/db.sqlite
lrwx------ 1 root root 64 Jun 22 11:49 18 -> /var/guix/db/db.sqlite-wal
lrwx------ 1 root root 64 Jun 22 11:49 19 -> /var/guix/db/db.sqlite-shm
l-wx------ 1 root root 64 Jun 22 11:49 2 -> 'pipe:[10239343]'
lrwx------ 1 root root 64 Jun 22 11:49 20 -> /var/guix/db/db.sqlite
lrwx------ 1 root root 64 Jun 22 11:49 21 -> /var/guix/db/db.sqlite-wal
lr-x------ 1 root root 64 Jun 22 11:49 3 -> 'pipe:[10021329]'
l-wx------ 1 root root 64 Jun 22 11:49 4 -> 'pipe:[10239345]'
lr-x------ 1 root root 64 Jun 22 11:49 40 -> /dev/urandom
l-wx------ 1 root root 64 Jun 22 11:49 5 -> 'pipe:[10021329]'
lr-x------ 1 root root 64 Jun 22 11:49 6 -> 'pipe:[10222125]'
l-wx------ 1 root root 64 Jun 22 11:49 7 -> 'pipe:[10222125]'
lr-x------ 1 root root 64 Jun 22 11:49 8 -> 'pipe:[10021332]'
l-wx------ 1 root root 64 Jun 22 11:49 9 -> 'pipe:[10021332]'
The are several possible causes of contention: (1) database opened too
many times, (2) database kept opened for too long, and (3) sqlite
mishandling contention somehow.
I think we can work on #1 and #2. As for #3, I wonder if there’s a
change in sqlite that could have made contention more contentious (ah
ha!), given that all this happened around the time of the last
‘core-updates’ merge, roughly corresponding to an upgrade from 3.24.0 to
3.31.0:
Maybe the most likely change that caused contention is that we increased
the number of machines (or rather the sum of build jobs that can be
handled by the build machines), and thus the number of parallel build
processes.
Ludo’.