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
?
Your comment

This issue is archived.

To comment on this conversation send an email to 62899@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 62899
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch