bug#55721: Low cache usage in the presence of grafts

[Ludovic Courtès]

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’.