Subject: Performance regression in cached ‘guix shell’

From: Ludovic Courtès <[email-masked]>
Date: Mon, 17 Apr 2023 14:31:14 +0200

Hello!

I noticed that ‘guix shell’ had become relatively slow on cache hits, as
in this example:

--8<---------------cut here---------------start------------->8---
$ 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
------ ----------- ----------- --------- --------- ------------------
 21.35    0.005453          37       147        20 futex
 18.17    0.004641        4641         1           wait4
 13.58    0.003470           4       837           mmap
 11.59    0.002960         493         6           clone
 11.51    0.002940           1      1835       326 newfstatat
  9.26    0.002365           2       950       290 openat
  7.85    0.002005           3       641           mprotect
  2.05    0.000524           0       661           close
  2.01    0.000514           3       135           read
  1.15    0.000295           0       601         3 lseek
  0.33    0.000085           3        25           rt_sigprocmask
  0.25    0.000065           3        20           brk
  0.22    0.000055           1        28           pread64
  0.13    0.000033           4         7           munmap
  0.10    0.000025           5         5           rt_sigaction
  0.08    0.000020          20         1           arch_prctl
  0.08    0.000020           6         3           prlimit64
  0.06    0.000016           2         6         1 ioctl
  0.06    0.000016           5         3           pipe2
  0.05    0.000012           0        16           clock_gettime
  0.03    0.000007           2         3           fcntl
  0.03    0.000007           7         1           set_tid_address
  0.03    0.000007           7         1           set_robust_list
  0.02    0.000005           2         2           sched_getaffinity
  0.01    0.000002           0         4           write
  0.01    0.000002           0        14           getpid
  0.00    0.000000           0         2         2 access
  0.00    0.000000           0         3           madvise
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0       115        97 readlink
  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           utimensat
  0.00    0.000000           0         2           getrandom
------ ----------- ----------- --------- --------- ------------------
100.00    0.025544           4      6084       739 total
$ guix describe
Generation 255  Apr 16 2023 22:56:42    (current)
  guix 9a5e1dc
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: 9a5e1dc1f16f5f8c056e64f2077b035784003673
--8<---------------cut here---------------end--------------->8---

The 950 ‘openat’ calls stem from opening lots of gnu/packages/* files,
which is unnecessary.

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

I think we should stick to ~0.1s startup time for cached ‘guix shell’,
as described in <https://issues.guix.gnu.org/50960#9>.

Ludo’.