bug#51787: GC takes more than 9 hours on berlin

["Ludovic Courtès" <ludo@gnu.org>]

Ludovic Courtès <ludo@gnu.org> skribis:

>   • Stracing the session’s guix-daemon process during GC suggests that
>     most of the time goes into I/O from ‘db.sqlite’.  It’s not
>     surprising because that GC phase is basically about browsing the
>     database, but it does seem to take a little too long for each store
>     item.

Stracing the client shows that the daemon spends several seconds on a
single store item occasionally:

--8<---------------cut here---------------start------------->8---
read(27, "gmlo\0\0\0\0", 8)             = 8 <0.363064>
read(27, "c\0\0\0\0\0\0\0", 8)          = 8 <0.000013>
read(27, "[95%] deleting '/gnu/store/p6r2jjy6frp682z3x94nvnmdh71p1p58-ecl-quicksearch-0.01"..., 104) = 104 <0.000010>
write(2, "[95%] deleting '/gnu/store/p6r2jjy6frp682z3x94nvnmdh71p1p58-ecl-quicksearch-0.01"..., 99) = 99 <0.000019>
read(27, "gmlo\0\0\0\0", 8)             = 8 <0.017863>
read(27, "^\0\0\0\0\0\0\0", 8)          = 8 <0.000019>
read(27, "[95%] deleting '/gnu/store/v6zd510kfmqd8j4w7q3zy9bid1fj96dk-shepherd-guix-daemon"..., 96) = 96 <0.000007>
write(2, "[95%] deleting '/gnu/store/v6zd510kfmqd8j4w7q3zy9bid1fj96dk-shepherd-guix-daemon"..., 94) = 94 <0.000012>
read(27, "gmlo\0\0\0\0", 8)             = 8 <5.861071>
read(27, "T\0\0\0\0\0\0\0", 8)          = 8 <0.000061>
read(27, "[95%] deleting '/gnu/store/0hpwig8cwdnzygjjzs9zjbxicvhif2vv-rust-bitvec-0.19.4.d"..., 88) = 88 <0.000087>
write(2, "[95%] deleting '/gnu/store/0hpwig8cwdnzygjjzs9zjbxicvhif2vv-rust-bitvec-0.19.4.d"..., 84) = 84 <0.000033>
--8<---------------cut here---------------end--------------->8---

(Notice ‘read’ taking 5.9s above.)

Ludo’.