GNU bug report logs -
#55721
Low cache usage in the presence of grafts
Previous Next
Reported by: Ludovic Courtès <ludo <at> gnu.org>
Date: Mon, 30 May 2022 08:44:01 UTC
Severity: important
Done: Ludovic Courtès <ludo <at> gnu.org>
Bug is archived. No further changes may be made.
Full log
View this message in rfc822 format
[Message part 1 (text/plain, inline)]
Your bug report
#55721: Low cache usage in the presence of grafts
which was filed against the guix package, has been closed.
The explanation is attached below, along with your original report.
If you require more details, please reply to 55721 <at> debbugs.gnu.org.
--
55721: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=55721
GNU Bug Tracking System
Contact help-debbugs <at> gnu.org with problems
[Message part 2 (message/rfc822, inline)]
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’.
[Message part 3 (message/rfc822, inline)]
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 <at> 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 <at> 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’.
This bug report was last modified 2 years and 355 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.