GNU bug report logs - #55721
Low cache usage in the presence of grafts

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 55721 in the body.
You can then email your comments to 55721 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: bug-guix <at> gnu.org
Subject: Low cache usage in the presence of grafts
Date: Mon, 30 May 2022 10:43:46 +0200

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

Message #10 received at 55721 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 55721 <at> debbugs.gnu.org
Subject: Re: bug#55721: Low cache usage in the presence of grafts
Date: Mon, 30 May 2022 11:31:47 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> 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:

[Message part 2 (text/x-patch, inline)]

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)))))

[Message part 3 (text/plain, inline)]

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

Message #13 received at 55721 <at> debbugs.gnu.org (full text, mbox):

From: Efraim Flashner <efraim <at> flashner.co.il>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 55721 <at> debbugs.gnu.org
Subject: Re: bug#55721: Low cache usage in the presence of grafts
Date: Mon, 30 May 2022 14:34:40 +0300

[Message part 1 (text/plain, inline)]

On Mon, May 30, 2022 at 11:31:47AM +0200, Ludovic Courtès wrote:
> Ludovic Courtès <ludo <at> 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 <at> 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

[signature.asc (application/pgp-signature, inline)]

Message #16 received at 55721 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Efraim Flashner <efraim <at> flashner.co.il>
Cc: 55721 <at> debbugs.gnu.org
Subject: Re: bug#55721: Low cache usage in the presence of grafts
Date: Mon, 30 May 2022 15:15:07 +0200

Hi,

Efraim Flashner <efraim <at> 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’.

Message #21 received at 55721-done <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 55721-done <at> debbugs.gnu.org
Subject: Re: bug#55721: Low cache usage in the presence of grafts
Date: Mon, 30 May 2022 16:38:52 +0200

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

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.