Performance regression in cached ‘guix shell’

  • Done
  • quality assurance status badge
Details
2 participants
  • Ludovic Courtès
  • Ludovic Courtès
Owner
unassigned
Submitted by
Ludovic Courtès
Severity
normal
L
L
Ludovic Courtès wrote on 17 Apr 2023 14:31
Performance regression in cached ‘guix shell ’
(address . bug-guix@gnu.org)
87ildug06l.fsf@inria.fr
Hello!

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

Toggle snippet (55 lines)
$ 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

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

Ludo’.
L
L
Ludovic Courtès wrote on 18 Apr 2023 00:53
Re: bug#62899: Performance regression in cached ‘ guix shell’
(address . 62899@debbugs.gnu.org)
875y9uazo3.fsf@gnu.org
Ludovic Courtès <ludovic.courtes@inria.fr> skribis:

Toggle quote (9 lines)
> $ 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
> ------ ----------- ----------- --------- --------- ------------------

[...]

Toggle quote (2 lines)
> 100.00 0.025544 4 6084 739 total

[...]

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

Fixed with 9fad6067d914066e3b80bc9da6a2cb8bb060b96d.

Toggle snippet (54 lines)
$ /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

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

Ludo’.
L
L
Ludovic Courtès wrote on 18 Apr 2023 00:53
control message for bug #62899
(address . control@debbugs.gnu.org)
874jpeazny.fsf@gnu.org
close 62899
quit
?