Low cache usage in the presence of grafts

  • Done
  • quality assurance status badge
Details
2 participants
  • Efraim Flashner
  • Ludovic Courtès
Owner
unassigned
Submitted by
Ludovic Courtès
Severity
important
L
L
Ludovic Courtès wrote on 30 May 2022 10:43
(address . bug-guix@gnu.org)
87y1yj5s1p.fsf@inria.fr
The use of per-session caches in the presence of grafts is
low—specifically when “build handlers” are invoked.

This is illustrated by the example below:

• the first run invokes the build handler of ‘map/accumulate-builds’
to download polkit (which has a ‘replacement’) and then proceeds
(the end result was already in store), taking no less than 6m of CPU
time;

• the second run doesn’t have to hop through the build handler since
everything is already in store and its takes 24s of CPU time.

Toggle snippet (71 lines)
$ guix gc -D $(guix build polkit --no-grafts)
finding garbage collector roots...
[0 MiB] deleting '/gnu/store/8vsfk8312m5p461wl4dq5lxjagfbwfhz-polkit-0.121'
deleting `/gnu/store/trash'
deleting unused links...
note: currently hard linking saves 72385.53 MiB
$ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
0.2 MB will be downloaded
polkit-0.121 198KiB 1.4MiB/s 00:00 [##################] 100.0%
/gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh
Reference Cache:
fresh caches: 8
lookups: 77581
hits: 52890 (68.2%)
cache size: 838 entries
Derivation graft cache:
fresh caches: 39
lookups: 704635
hits: 627819 (89.1%)
cache size: 2946 entries
Remote procedure call summary: 33071 RPCs
built-in-builders ... 1
query-substitutable-path-infos ... 2
build-things ... 2
add-to-store/tree ... 56
valid-path? ... 59
add-to-store ... 373
add-text-to-store ... 7887
query-references ... 24691

real 5m6.727s
user 6m59.438s
sys 0m1.633s
$ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
/gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh
Reference Cache:
fresh caches: 1
lookups: 2988
hits: 2150 (72.0%)
cache size: 838 entries
Derivation graft cache:
fresh caches: 5
lookups: 28323
hits: 25376 (89.6%)
cache size: 2946 entries
Remote procedure call summary: 9159 RPCs
query-substitutable-path-infos ... 1
build-things ... 1
built-in-builders ... 1
valid-path? ... 2
add-to-store/tree ... 56
add-to-store ... 373
query-references ... 838
add-text-to-store ... 7887

real 0m17.304s
user 0m24.620s
sys 0m0.273s
$ git log |head
commit acb08304c862d65679086a9f160240bfd598289d
Author: Wiktor Zelazny <wzelazny@vurv.cz>
Date: Wed May 18 16:20:30 2022 +0000

gnu: Add python-gpy.
* gnu/packages/python-science.scm (python-gpy): New variable.
Signed-off-by: Ludovic Courtès <ludo@gnu.org>


From the first run we can see that the reference cache (used by
‘references/cached’, itself called form (guix grafts)) is almost unused
since we end up making 24K ‘query-references’ RPCs for only 838 entries
in that cache, meaning the same work is done ~29 times.

My hypothesis is that this is a regression introduced by the switch to
“functional caches” in ‘core-updates’ back in
9e5812ac59b01ff011ec0c5b0f437dfe85d6fcc7.

Ludo’.
L
L
Ludovic Courtès wrote on 30 May 2022 11:09
control message for bug #55721
(address . control@debbugs.gnu.org)
87wne35quy.fsf@gnu.org
severity 55721 important
quit
L
L
Ludovic Courtès wrote on 30 May 2022 11:31
Re: bug#55721: Low cache usage in the presence of grafts
(address . 55721@debbugs.gnu.org)
87pmjv5pto.fsf@gnu.org
Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (28 lines)
> $ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
> 0.2 MB will be downloaded
> polkit-0.121 198KiB 1.4MiB/s 00:00 [##################] 100.0%
> /gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh
> Reference Cache:
> fresh caches: 8
> lookups: 77581
> hits: 52890 (68.2%)
> cache size: 838 entries
> Derivation graft cache:
> fresh caches: 39
> lookups: 704635
> hits: 627819 (89.1%)
> cache size: 2946 entries
> Remote procedure call summary: 33071 RPCs
> built-in-builders ... 1
> query-substitutable-path-infos ... 2
> build-things ... 2
> add-to-store/tree ... 56
> valid-path? ... 59
> add-to-store ... 373
> add-text-to-store ... 7887
> query-references ... 24691
>
> real 5m6.727s
> user 6m59.438s
> sys 0m1.633s

With this patch:
Toggle diff (28 lines)
diff --git a/guix/store.scm b/guix/store.scm
index efba07bdcd..88cab1bb6a 100644
--- a/guix/store.scm
+++ b/guix/store.scm
@@ -1337,7 +1337,12 @@ (define (build-accumulator expected-store)
(if (and (eq? (store-connection-socket store)
(store-connection-socket expected-store))
(= mode (build-mode normal)))
- (unresolved things continue)
+ (unresolved things
+ (lambda (new-store value)
+ ;; Borrow caches from NEW-STORE.
+ (set-store-connection-caches!
+ store (store-connection-caches new-store))
+ (continue value)))
(continue #t))))
(define default-cutoff
@@ -1397,7 +1402,8 @@ (define-values (result rest)
(if (unresolved? obj)
;; Pass #f because 'build-things' is now
;; unnecessary.
- ((unresolved-continuation obj) #f)
+ ((unresolved-continuation obj)
+ store #f)
obj))
result #:cutoff cutoff)
(map/accumulate-builds store proc rest #:cutoff cutoff)))))
… we’re doing better:

Toggle snippet (35 lines)
$ guix gc -D $(guix build polkit --no-grafts)
finding garbage collector roots...
[0 MiB] deleting '/gnu/store/8vsfk8312m5p461wl4dq5lxjagfbwfhz-polkit-0.121'
deleting `/gnu/store/trash'
deleting unused links...
note: currently hard linking saves 72397.13 MiB
$ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
0.2 MB will be downloaded
polkit-0.121 198KiB 1.6MiB/s 00:00 [##################] 100.0%
/gnu/store/wp3lv4xrh6vw79gnkyi5471c1l8j624n-run-vm.sh
Reference Cache:
fresh caches: 8
lookups: 17232
hits: 14816 (86.0%)
cache size: 784 entries
Derivation graft cache:
fresh caches: 39
lookups: 128402
hits: 111336 (86.7%)
cache size: 328 entries
Remote procedure call summary: 10796 RPCs
built-in-builders ... 1
query-substitutable-path-infos ... 2
build-things ... 2
add-to-store/tree ... 56
valid-path? ... 59
add-to-store ... 373
query-references ... 2416
add-text-to-store ... 7887

real 1m31.550s
user 2m7.107s
sys 0m0.637s

There’s still room for improvement though.

Ludo’.
E
E
Efraim Flashner wrote on 30 May 2022 13:34
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 55721@debbugs.gnu.org)
YpSr0FgN0CENUyZU@3900XT
On Mon, May 30, 2022 at 11:31:47AM +0200, Ludovic Courtès wrote:
Toggle quote (105 lines)
> Ludovic Courtès <ludo@gnu.org> skribis:
>
> > $ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
> > 0.2 MB will be downloaded
> > polkit-0.121 198KiB 1.4MiB/s 00:00 [##################] 100.0%
> > /gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh
> > Reference Cache:
> > fresh caches: 8
> > lookups: 77581
> > hits: 52890 (68.2%)
> > cache size: 838 entries
> > Derivation graft cache:
> > fresh caches: 39
> > lookups: 704635
> > hits: 627819 (89.1%)
> > cache size: 2946 entries
> > Remote procedure call summary: 33071 RPCs
> > built-in-builders ... 1
> > query-substitutable-path-infos ... 2
> > build-things ... 2
> > add-to-store/tree ... 56
> > valid-path? ... 59
> > add-to-store ... 373
> > add-text-to-store ... 7887
> > query-references ... 24691
> >
> > real 5m6.727s
> > user 6m59.438s
> > sys 0m1.633s
>
> With this patch:
>

> diff --git a/guix/store.scm b/guix/store.scm
> index efba07bdcd..88cab1bb6a 100644
> --- a/guix/store.scm
> +++ b/guix/store.scm
> @@ -1337,7 +1337,12 @@ (define (build-accumulator expected-store)
> (if (and (eq? (store-connection-socket store)
> (store-connection-socket expected-store))
> (= mode (build-mode normal)))
> - (unresolved things continue)
> + (unresolved things
> + (lambda (new-store value)
> + ;; Borrow caches from NEW-STORE.
> + (set-store-connection-caches!
> + store (store-connection-caches new-store))
> + (continue value)))
> (continue #t))))
>
> (define default-cutoff
> @@ -1397,7 +1402,8 @@ (define-values (result rest)
> (if (unresolved? obj)
> ;; Pass #f because 'build-things' is now
> ;; unnecessary.
> - ((unresolved-continuation obj) #f)
> + ((unresolved-continuation obj)
> + store #f)
> obj))
> result #:cutoff cutoff)
> (map/accumulate-builds store proc rest #:cutoff cutoff)))))

>
> … we’re doing better:
>
> --8<---------------cut here---------------start------------->8---
> $ guix gc -D $(guix build polkit --no-grafts)
> finding garbage collector roots...
> [0 MiB] deleting '/gnu/store/8vsfk8312m5p461wl4dq5lxjagfbwfhz-polkit-0.121'
> deleting `/gnu/store/trash'
> deleting unused links...
> note: currently hard linking saves 72397.13 MiB
> $ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
> 0.2 MB will be downloaded
> polkit-0.121 198KiB 1.6MiB/s 00:00 [##################] 100.0%
> /gnu/store/wp3lv4xrh6vw79gnkyi5471c1l8j624n-run-vm.sh
> Reference Cache:
> fresh caches: 8
> lookups: 17232
> hits: 14816 (86.0%)
> cache size: 784 entries
> Derivation graft cache:
> fresh caches: 39
> lookups: 128402
> hits: 111336 (86.7%)
> cache size: 328 entries
> Remote procedure call summary: 10796 RPCs
> built-in-builders ... 1
> query-substitutable-path-infos ... 2
> build-things ... 2
> add-to-store/tree ... 56
> valid-path? ... 59
> add-to-store ... 373
> query-references ... 2416
> add-text-to-store ... 7887
>
> real 1m31.550s
> user 2m7.107s
> sys 0m0.637s
> --8<---------------cut here---------------end--------------->8---
>
> There’s still room for improvement though.
>
> Ludo’.

With that change you've dropped the query-references from 24691 to 2416,
more than a 90% drop. If you want to take aim at improving it further
I'd say take a look at add-text-to-store and see if you can shrink that
number.

--
Efraim Flashner <efraim@flashner.co.il> ????? ?????
GPG key = A28B F40C 3E55 1372 662D 14F7 41AA E7DC CA3D 8351
Confidentiality cannot be guaranteed on emails sent or received unencrypted
-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEoov0DD5VE3JmLRT3Qarn3Mo9g1EFAmKUq80ACgkQQarn3Mo9
g1GdUQ/+N9nCWMi99+De+8gC7kx0N9TfrtbVt0W6vNuzuhc2g5CjDV0/Wm6foo6W
08Mn7bqwMdXJZ4zQshYq5WTKo38Yeie5C7xQ6dFp8cyrWMkicBPhig/XGfo3Whto
A3BZ2xOtmpDclUlpwaF4GOxXbcgAEPxLutAjtZYsK4SJdxysAnKEbcWmDQqhFp4G
wNZH0ubpnIp2LODdBDi9iL8RmrhUNIhIbFucNYM+QKUGM0A5717vNjS4p/BLPkGu
Bw4uqPutweFuvVushzobTctLBN4C9jaizsneukKwBqeZyQSzWqk0j9b1UuUg+3Ev
8bqBL4l0+Jpw/KNl37MNAQ8WZ5gjp92NxfWNeMUDdEweN2eN0sFlEjcDLzVAK5Uc
99+6L4ZsNdlt6cpmmS8zI5pdEvtQCVl9uIzXjXYvexkOjk0cbElXctNv6sPSPhpg
HvImJbQTqyGCafQdBaS8V4L5xp7c2TalGooCDgA4nb+vKLy8o5v/36sGA6OjcNp4
uLVV5uzI+U4Ts3UrcHO59/hFy8ZHpE0FKkFzD1PChIIFa5Yt3sMB+d9xjRFsW8pg
+iwL85Hgc0DbPhYr9YlB3Onmzj1N01xikLbX9fgJ/2hKNjADxb3c7bqX+nUOBQIa
/nvX/GZJlSq0g20lHiPAkRo3w0P1iTBRZxzSs7A5YnfskaqePAk=
=f62t
-----END PGP SIGNATURE-----


L
L
Ludovic Courtès wrote on 30 May 2022 15:15
(name . Efraim Flashner)(address . efraim@flashner.co.il)(address . 55721@debbugs.gnu.org)
87bkvf5fhg.fsf@gnu.org
Hi,

Efraim Flashner <efraim@flashner.co.il> skribis:

Toggle quote (5 lines)
> With that change you've dropped the query-references from 24691 to 2416,
> more than a 90% drop. If you want to take aim at improving it further
> I'd say take a look at add-text-to-store and see if you can shrink that
> number.

That’s not related to grafts though: these ‘add-text-to-store’ RPCs
correspond to adding the *-guile-builder files to the store, roughly one
per package.

This could be improved, for instance by having a single *-guile-builder
script for all of ‘gnu-build-system’; that requires a bit of work.

Ludo’.
L
L
Ludovic Courtès wrote on 30 May 2022 16:38
(address . 55721-done@debbugs.gnu.org)
877d633x1f.fsf@gnu.org
I pushed a variant of the patch I sent as
1ae0e1dc29109cef20dbe9d26eb1c855694716b5.

What I get now is:

Toggle snippet (40 lines)
$ guix gc -D $(guix build polkit --no-grafts)
finding garbage collector roots...
[0 MiB] deleting '/gnu/store/8vsfk8312m5p461wl4dq5lxjagfbwfhz-polkit-0.121'
deleting `/gnu/store/trash'
deleting unused links...
note: currently hard linking saves 72523.68 MiB
$ time GUIX_PROFILING="rpc reference-cache derivation-graft-cache" ./pre-inst-env guix system vm gnu/system/examples/desktop.tmpl
0.2 MB will be downloaded
polkit-0.121 198KiB 1.4MiB/s 00:00 [##################] 100.0%
/gnu/store/cvfw1jlf9m60s4yjxhnjjv68rg59giag-run-vm.sh
guix system: warning: only 4.7 GiB of free space available on /gnu/store
hint: Consider deleting old profile generations and collecting garbage, along these lines:

guix gc --delete-generations=1m

Reference Cache:
fresh caches: 1
lookups: 13997
hits: 13091 (93.5%)
cache size: 838 entries
Derivation graft cache:
fresh caches: 5
lookups: 117280
hits: 103398 (88.2%)
cache size: 430 entries
Remote procedure call summary: 9286 RPCs
built-in-builders ... 1
query-substitutable-path-infos ... 2
build-things ... 2
add-to-store/tree ... 56
valid-path? ... 59
add-to-store ... 373
query-references ... 906
add-text-to-store ... 7887

real 0m45.089s
user 1m5.976s
sys 0m0.433s

We’re still getting a few extra ‘query-references’ RPCs, but it’s much
better.

Ludo’.
Closed
?