Subject: Re: bug#62899: Performance regression in cached ‘guix shell’

From: Ludovic Courtès <[email-masked]>
Date: Tue, 18 Apr 2023 00:53:32 +0200

Ludovic Courtès <[email-masked]> skribis:

> $ time guix shell -D guix -- true
>
> real    0m0.596s
> user    0m0.716s
> sys     0m0.064s
> $ strace -c guix shell -D guix -- true
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ------------------

[...]

> 100.00    0.025544           4      6084       739 total

[...]

> This, in turn, comes from (guix scripts pack), which has become a hard
> dependency of (guix scripts environment) with commit
> b31ea797edb4f6e8c14e8fe790da1319607c5cb1.

Fixed with 9fad6067d914066e3b80bc9da6a2cb8bb060b96d.

--8<---------------cut here---------------start------------->8---
$ /tmp/prof/bin/guix describe
Generation 1    Apr 18 2023 00:49:35    (current)
  guix 84bd7cf
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: 84bd7cf9189574d9a966c4583f95bfe843e4b56a
$ strace -c /tmp/prof/bin/guix shell -D guix -- true
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 36.04    0.002646        2646         1           wait4
 20.68    0.001518          16        93        12 futex
 10.97    0.000805           2       364           mmap
 10.11    0.000742           1       522       281 openat
  8.20    0.000602           0      1001       328 newfstatat
  4.15    0.000305           1       236           mprotect
  3.39    0.000249           1       133           read
  1.59    0.000117           1       104        88 readlink
  1.43    0.000105           0       242           close
  0.79    0.000058           9         6           clone
  0.53    0.000039           0       195         3 lseek
  0.44    0.000032           1        21           rt_sigprocmask
  0.38    0.000028           1        22           brk
  0.31    0.000023           0        28           pread64
  0.23    0.000017           8         2           munmap
  0.16    0.000012           1        10           clock_gettime
  0.12    0.000009           1         5           rt_sigaction
  0.12    0.000009           3         3           pipe2
  0.08    0.000006           3         2           sched_getaffinity
  0.07    0.000005           1         3           prlimit64
  0.04    0.000003           0         6         1 ioctl
  0.04    0.000003           3         1           set_tid_address
  0.04    0.000003           3         1           set_robust_list
  0.03    0.000002           0         3           write
  0.03    0.000002           2         1           getcwd
  0.01    0.000001           0         2           getrandom
  0.00    0.000000           0         2         2 access
  0.00    0.000000           0        14           getpid
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           sysinfo
  0.00    0.000000           0         2           getuid
  0.00    0.000000           0         2           geteuid
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           utimensat
------ ----------- ----------- --------- --------- ------------------
100.00    0.007341           2      3035       715 total
$ time /tmp/prof/bin/guix shell -D guix -- true

real    0m0.155s
user    0m0.143s
sys     0m0.049s
--8<---------------cut here---------------end--------------->8---

There’s still room for improvement but at least no gnu/packages/* files
are being loaded now.

Ludo’.