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 <wzela...@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 <l...@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’.
