Possible useful guix package performance data

Possible useful guix package performance data

[Evan Cooney]

[-- Attachment #1: Type: text/plain, Size: 653 bytes --]

Hi everyone, I used guile's statprof profiler to collect some performance
data for guix package. I added the profiler by using the statprof module in
guix/guix/scripts/package.scm and wrapping the call to guix-package* in the
guix package define command thing in a lambda, then in statprof. Here is
the code: paste.debian.net/1334168
I collected this data by running guix package -i krita inkscape
rust-rustup-toolchain. It uses a significant amount of time in the garbage
collector (~75% of total runtime) and ~45% of time is spend calling append.
What do y'all make of this? Here is the full data: paste.debian.net/1334174

Happy hacking!
Evan Cooney

[-- Attachment #2: Type: text/html, Size: 868 bytes --]

Re: Possible useful guix package performance data

[Thompson, David]

Hi Evan,

On Fri, Nov 1, 2024 at 2:28 AM Evan Cooney <evancooney71@gmail.com> wrote:
>
> Hi everyone, I used guile's statprof profiler to collect some performance data for guix package. I added the profiler by using the statprof module in guix/guix/scripts/package.scm and wrapping the call to guix-package* in the guix package define command thing in a lambda, then in statprof. Here is the code: paste.debian.net/1334168
> I collected this data by running guix package -i krita inkscape rust-rustup-toolchain. It uses a significant amount of time in the garbage collector (~75% of total runtime) and ~45% of time is spend calling append. What do y'all make of this? Here is the full data: paste.debian.net/1334174

What are you trying to measure, exactly? The data collected is about a
single thread of a Guile process, but `guix package -i` involves
interaction with the Guix build daemon, waiting for downloads, etc.
These things are outside the scope of what statprof is tracing.
Anything that involves reaching out to the internet is going to make
for an unreliable benchmark. I'm not actively working on Guix tools
but I don't see anything immediately actionable from the collected
data. I think getting some more clarity around the goal is necessary
in order to know what to profile and how.

- Dave

Re: Possible useful guix package performance data

[Ludovic Courtès]

Hi,

"Thompson, David" <dthompson2@worcester.edu> skribis:

> What are you trying to measure, exactly? The data collected is about a
> single thread of a Guile process, but `guix package -i` involves
> interaction with the Guix build daemon, waiting for downloads, etc.
> These things are outside the scope of what statprof is tracing.
> Anything that involves reaching out to the internet is going to make
> for an unreliable benchmark. I'm not actively working on Guix tools
> but I don't see anything immediately actionable from the collected
> data. I think getting some more clarity around the goal is necessary
> in order to know what to profile and how.

Unless you’re specifically looking at performance of substitutes, I
recommend looking at profiles when using ‘--no-substitutes’; I would
also pass ‘--no-grafts’, to make sure you’re really looking at the core
of the whole package-to-derivation mechanism.

You may also want to check the ‘GUIX_PROFILING’ environment variable,
from the (guix profiling) module.  That can give a useful overview such
as the number of remote procedure calls (RPCs) made to guix-daemon and
the hit rate of the “object cache”:

--8<---------------cut here---------------start------------->8---
$ GUIX_PROFILING="gc rpc object-cache" guix build hello -d --no-grafts --no-substitutes
/gnu/store/79dhya6sngg4rf53m1cyxlhn8y4pnw2n-hello-2.12.1.drv
Object Cache:
  fresh caches:    16
  lookups:       5042
  hits:          4596 (91.2%)
  cache size:     445 entries
Remote procedure call summary: 382 RPCs
  built-in-builders              ...     1
  add-to-store/tree              ...     3
  add-to-store                   ...    48
  add-text-to-store              ...   330
Garbage collection statistics:
  heap size:        72.27 MiB
  allocated:        100.29 MiB
  GC times:         13
  time spent in GC: 0.42 seconds (45% of user time)
--8<---------------cut here---------------end--------------->8---

Keep in mind that the figures we’re looking at here are largely
dependent of the package graph being processed (that of ‘hello’ here).
So it also makes sense to look at the size of the package graph in
question first (in the case of ‘hello’, it’s probably fine, but let’s
say when Rust packages are in the loop, the graph might be much bigger
than needed/expected).

HTH,
Ludo’.

Re: Possible useful guix package performance data

[Efraim Flashner]

[-- Attachment #1: Type: text/plain, Size: 4379 bytes --]

On Mon, Nov 04, 2024 at 11:22:01PM +0100, Ludovic Courtès wrote:
> Hi,
> 
> "Thompson, David" <dthompson2@worcester.edu> skribis:
> 
> > What are you trying to measure, exactly? The data collected is about a
> > single thread of a Guile process, but `guix package -i` involves
> > interaction with the Guix build daemon, waiting for downloads, etc.
> > These things are outside the scope of what statprof is tracing.
> > Anything that involves reaching out to the internet is going to make
> > for an unreliable benchmark. I'm not actively working on Guix tools
> > but I don't see anything immediately actionable from the collected
> > data. I think getting some more clarity around the goal is necessary
> > in order to know what to profile and how.
> 
> Unless you’re specifically looking at performance of substitutes, I
> recommend looking at profiles when using ‘--no-substitutes’; I would
> also pass ‘--no-grafts’, to make sure you’re really looking at the core
> of the whole package-to-derivation mechanism.
> 
> You may also want to check the ‘GUIX_PROFILING’ environment variable,
> from the (guix profiling) module.  That can give a useful overview such
> as the number of remote procedure calls (RPCs) made to guix-daemon and
> the hit rate of the “object cache”:
> 
> --8<---------------cut here---------------start------------->8---
> $ GUIX_PROFILING="gc rpc object-cache" guix build hello -d --no-grafts --no-substitutes
> /gnu/store/79dhya6sngg4rf53m1cyxlhn8y4pnw2n-hello-2.12.1.drv
> Object Cache:
>   fresh caches:    16
>   lookups:       5042
>   hits:          4596 (91.2%)
>   cache size:     445 entries
> Remote procedure call summary: 382 RPCs
>   built-in-builders              ...     1
>   add-to-store/tree              ...     3
>   add-to-store                   ...    48
>   add-text-to-store              ...   330
> Garbage collection statistics:
>   heap size:        72.27 MiB
>   allocated:        100.29 MiB
>   GC times:         13
>   time spent in GC: 0.42 seconds (45% of user time)
> --8<---------------cut here---------------end--------------->8---
> 
> Keep in mind that the figures we’re looking at here are largely
> dependent of the package graph being processed (that of ‘hello’ here).
> So it also makes sense to look at the size of the package graph in
> question first (in the case of ‘hello’, it’s probably fine, but let’s
> say when Rust packages are in the loop, the graph might be much bigger
> than needed/expected).

Did someone say rust?

I made a manifest of the packages that use the cargo-build-system and
aren't rust-* packages, or which have rust as an input. 102 packages:

$ GUIX_PROFILING="gc rpc object-cache" ./pre-inst-env guix build \
        --no-grafts -m ./etc/teams/rust/rusty-packages.scm \
        --no-substitutes -d

Object Cache:
  fresh caches:    20
  lookups:      361239
  hits:         351403 (97.3%)
  cache size:    9835 entries
Remote procedure call summary: 11780 RPCs
  built-in-builders              ...     1
  add-to-store/tree              ...    33
  add-to-store                   ...   329
  add-text-to-store              ... 11417
Garbage collection statistics:
  heap size:        223.68 MiB
  allocated:        1332.86 MiB
  GC times:         34
  time spent in GC: 7.10 seconds (33% of user time)

I also did a run with hello to get a comparison on the same machine:

$ GUIX_PROFILING="gc rpc object-cache" ./pre-inst-env guix build hello -d --no-grafts --no-substitutes
/gnu/store/1y2k2jkb8w67mcwj42b8bxjv3yshk5kf-hello-2.12.1.drv
Object Cache:
  fresh caches:    16
  lookups:       5042
  hits:          4596 (91.2%)
  cache size:     445 entries
Remote procedure call summary: 382 RPCs
  built-in-builders              ...     1
  add-to-store/tree              ...     3
  add-to-store                   ...    48
  add-text-to-store              ...   330
Garbage collection statistics:
  heap size:        79.57 MiB
  allocated:        122.75 MiB
  GC times:         14
  time spent in GC: 0.94 seconds (69% of user time)

-- 
Efraim Flashner   <efraim@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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Possible useful guix package performance data

[Evan Cooney]

[-- Attachment #1: Type: text/plain, Size: 4704 bytes --]

Hi,

This is amazingly helpful!! Thank you!

On Tue, Nov 5, 2024, 9:34 AM Efraim Flashner <efraim@flashner.co.il> wrote:

> On Mon, Nov 04, 2024 at 11:22:01PM +0100, Ludovic Courtès wrote:
> > Hi,
> >
> > "Thompson, David" <dthompson2@worcester.edu> skribis:
> >
> > > What are you trying to measure, exactly? The data collected is about a
> > > single thread of a Guile process, but `guix package -i` involves
> > > interaction with the Guix build daemon, waiting for downloads, etc.
> > > These things are outside the scope of what statprof is tracing.
> > > Anything that involves reaching out to the internet is going to make
> > > for an unreliable benchmark. I'm not actively working on Guix tools
> > > but I don't see anything immediately actionable from the collected
> > > data. I think getting some more clarity around the goal is necessary
> > > in order to know what to profile and how.
> >
> > Unless you’re specifically looking at performance of substitutes, I
> > recommend looking at profiles when using ‘--no-substitutes’; I would
> > also pass ‘--no-grafts’, to make sure you’re really looking at the core
> > of the whole package-to-derivation mechanism.
> >
> > You may also want to check the ‘GUIX_PROFILING’ environment variable,
> > from the (guix profiling) module.  That can give a useful overview such
> > as the number of remote procedure calls (RPCs) made to guix-daemon and
> > the hit rate of the “object cache”:
> >
> > --8<---------------cut here---------------start------------->8---
> > $ GUIX_PROFILING="gc rpc object-cache" guix build hello -d --no-grafts
> --no-substitutes
> > /gnu/store/79dhya6sngg4rf53m1cyxlhn8y4pnw2n-hello-2.12.1.drv
> > Object Cache:
> >   fresh caches:    16
> >   lookups:       5042
> >   hits:          4596 (91.2%)
> >   cache size:     445 entries
> > Remote procedure call summary: 382 RPCs
> >   built-in-builders              ...     1
> >   add-to-store/tree              ...     3
> >   add-to-store                   ...    48
> >   add-text-to-store              ...   330
> > Garbage collection statistics:
> >   heap size:        72.27 MiB
> >   allocated:        100.29 MiB
> >   GC times:         13
> >   time spent in GC: 0.42 seconds (45% of user time)
> > --8<---------------cut here---------------end--------------->8---
> >
> > Keep in mind that the figures we’re looking at here are largely
> > dependent of the package graph being processed (that of ‘hello’ here).
> > So it also makes sense to look at the size of the package graph in
> > question first (in the case of ‘hello’, it’s probably fine, but let’s
> > say when Rust packages are in the loop, the graph might be much bigger
> > than needed/expected).
>
> Did someone say rust?
>
> I made a manifest of the packages that use the cargo-build-system and
> aren't rust-* packages, or which have rust as an input. 102 packages:
>
> $ GUIX_PROFILING="gc rpc object-cache" ./pre-inst-env guix build \
>         --no-grafts -m ./etc/teams/rust/rusty-packages.scm \
>         --no-substitutes -d
>
> Object Cache:
>   fresh caches:    20
>   lookups:      361239
>   hits:         351403 (97.3%)
>   cache size:    9835 entries
> Remote procedure call summary: 11780 RPCs
>   built-in-builders              ...     1
>   add-to-store/tree              ...    33
>   add-to-store                   ...   329
>   add-text-to-store              ... 11417
> Garbage collection statistics:
>   heap size:        223.68 MiB
>   allocated:        1332.86 MiB
>   GC times:         34
>   time spent in GC: 7.10 seconds (33% of user time)
>
> I also did a run with hello to get a comparison on the same machine:
>
> $ GUIX_PROFILING="gc rpc object-cache" ./pre-inst-env guix build hello -d
> --no-grafts --no-substitutes
> /gnu/store/1y2k2jkb8w67mcwj42b8bxjv3yshk5kf-hello-2.12.1.drv
> Object Cache:
>   fresh caches:    16
>   lookups:       5042
>   hits:          4596 (91.2%)
>   cache size:     445 entries
> Remote procedure call summary: 382 RPCs
>   built-in-builders              ...     1
>   add-to-store/tree              ...     3
>   add-to-store                   ...    48
>   add-text-to-store              ...   330
> Garbage collection statistics:
>   heap size:        79.57 MiB
>   allocated:        122.75 MiB
>   GC times:         14
>   time spent in GC: 0.94 seconds (69% of user time)
>
> --
> Efraim Flashner   <efraim@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
>

[-- Attachment #2: Type: text/html, Size: 5852 bytes --]

Re: Possible useful guix package performance data

[Simon Tournier]

Hi,

On Mon, 04 Nov 2024 at 23:22, Ludovic Courtès <ludo@gnu.org> wrote:

> Garbage collection statistics:
>   heap size:        72.27 MiB
>   allocated:        100.29 MiB
>   GC times:         13
>   time spent in GC: 0.42 seconds (45% of user time)

I am puzzled by this.  Well, most of the time when the garbage
collection takes a relative amount of time compared to the whole task,
it potentially means some allocations are poorly designed.

How could I inspect that?


Cheers,
simon