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
?
Your comment

This issue is archived.

To comment on this conversation send an email to 55721@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 55721
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch