Subject: bug#55721: closed (Re: bug#55721: Low cache usage in the presence of grafts)

From: [email-masked] (GNU bug Tracking System)
Date: Mon, 30 May 2022 14:40:02 +0000

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 [email-masked].

-- 
55721: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=55721
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: bug#55721: Low cache usage in the presence of grafts
From: Ludovic Courtès <[email-masked]>
To: [email-masked]
Date: Mon, 30 May 2022 16:38:52 +0200
List-Id: <debbugs-submit.debbugs.gnu.org>

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

Subject: Low cache usage in the presence of grafts
From: Ludovic Courtès <[email-masked]>
To: [email-masked]
Date: Mon, 30 May 2022 10:43:46 +0200
List-Id: <debbugs-submit.debbugs.gnu.org>

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 <[email-masked]>
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 <[email-masked]>

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