GNU bug report logs -
#62899
Performance regression in cached ‘guix shell’
Previous Next
To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 62899 in the body.
You can then email your comments to 62899 AT debbugs.gnu.org in the normal way.
Toggle the display of automated, internal messages from the tracker.
Report forwarded
to
bug-guix <at> gnu.org:
bug#62899; Package
guix.
(Mon, 17 Apr 2023 12:32:02 GMT)
Full text and
rfc822 format available.
Acknowledgement sent
to
Ludovic Courtès <ludovic.courtes <at> inria.fr>:
New bug report received and forwarded. Copy sent to
bug-guix <at> gnu.org.
(Mon, 17 Apr 2023 12:32:02 GMT)
Full text and
rfc822 format available.
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
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’.
Information forwarded
to
bug-guix <at> gnu.org:
bug#62899; Package
guix.
(Mon, 17 Apr 2023 22:54:02 GMT)
Full text and
rfc822 format available.
Message #8 received at 62899 <at> debbugs.gnu.org (full text, mbox):
Ludovic Courtès <ludovic.courtes <at> inria.fr> 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’.
bug closed, send any further explanations to
62899 <at> debbugs.gnu.org and Ludovic Courtès <ludovic.courtes <at> inria.fr>
Request was from
Ludovic Courtès <ludo <at> gnu.org>
to
control <at> debbugs.gnu.org.
(Mon, 17 Apr 2023 22:54:02 GMT)
Full text and
rfc822 format available.
bug archived.
Request was from
Debbugs Internal Request <help-debbugs <at> gnu.org>
to
internal_control <at> debbugs.gnu.org.
(Tue, 16 May 2023 11:24:08 GMT)
Full text and
rfc822 format available.
This bug report was last modified 2 years and 36 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.