* bug#55721: Low cache usage in the presence of grafts
@ 2022-05-30 8:43 Ludovic Courtès
2022-05-30 9:31 ` Ludovic Courtès
0 siblings, 1 reply; 5+ messages in thread
From: Ludovic Courtès @ 2022-05-30 8:43 UTC (permalink / raw)
To: 55721
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.
--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 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>
--8<---------------cut here---------------end--------------->8---
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’.
^ permalink raw reply [flat|nested] 5+ messages in thread* bug#55721: Low cache usage in the presence of grafts
2022-05-30 8:43 bug#55721: Low cache usage in the presence of grafts Ludovic Courtès
@ 2022-05-30 9:31 ` Ludovic Courtès
2022-05-30 11:34 ` Efraim Flashner
2022-05-30 14:38 ` Ludovic Courtès
0 siblings, 2 replies; 5+ messages in thread
From: Ludovic Courtès @ 2022-05-30 9:31 UTC (permalink / raw)
To: 55721
[-- Attachment #1: Type: text/plain, Size: 1182 bytes --]
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:
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 1369 bytes --]
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)))))
[-- Attachment #3: Type: text/plain, Size: 1552 bytes --]
… 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’.
^ permalink raw reply related [flat|nested] 5+ messages in thread* bug#55721: Low cache usage in the presence of grafts
2022-05-30 9:31 ` Ludovic Courtès
@ 2022-05-30 11:34 ` Efraim Flashner
2022-05-30 13:15 ` Ludovic Courtès
2022-05-30 14:38 ` Ludovic Courtès
1 sibling, 1 reply; 5+ messages in thread
From: Efraim Flashner @ 2022-05-30 11:34 UTC (permalink / raw)
To: Ludovic Courtès; +Cc: 55721
[-- Attachment #1: Type: text/plain, Size: 4848 bytes --]
On Mon, May 30, 2022 at 11:31:47AM +0200, Ludovic Courtès wrote:
> 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
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 5+ messages in thread
* bug#55721: Low cache usage in the presence of grafts
2022-05-30 11:34 ` Efraim Flashner
@ 2022-05-30 13:15 ` Ludovic Courtès
0 siblings, 0 replies; 5+ messages in thread
From: Ludovic Courtès @ 2022-05-30 13:15 UTC (permalink / raw)
To: Efraim Flashner; +Cc: 55721
Hi,
Efraim Flashner <efraim@flashner.co.il> skribis:
> 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’.
^ permalink raw reply [flat|nested] 5+ messages in thread
* bug#55721: Low cache usage in the presence of grafts
2022-05-30 9:31 ` Ludovic Courtès
2022-05-30 11:34 ` Efraim Flashner
@ 2022-05-30 14:38 ` Ludovic Courtès
1 sibling, 0 replies; 5+ messages in thread
From: Ludovic Courtès @ 2022-05-30 14:38 UTC (permalink / raw)
To: 55721-done
I pushed a variant of the patch I sent as
1ae0e1dc29109cef20dbe9d26eb1c855694716b5.
What I get now is:
--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 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
--8<---------------cut here---------------end--------------->8---
We’re still getting a few extra ‘query-references’ RPCs, but it’s much
better.
Ludo’.
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2022-05-30 14:41 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-05-30 8:43 bug#55721: Low cache usage in the presence of grafts Ludovic Courtès
2022-05-30 9:31 ` Ludovic Courtès
2022-05-30 11:34 ` Efraim Flashner
2022-05-30 13:15 ` Ludovic Courtès
2022-05-30 14:38 ` Ludovic Courtès
Code repositories for project(s) associated with this public inbox
https://git.savannah.gnu.org/cgit/guix.git
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).