* bug#62899: Performance regression in cached ‘guix shell’
@ 2023-04-17 12:31 Ludovic Courtès
2023-04-17 22:53 ` Ludovic Courtès
0 siblings, 1 reply; 2+ messages in thread
From: Ludovic Courtès @ 2023-04-17 12:31 UTC (permalink / raw)
To: 62899
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’.
^ permalink raw reply [flat|nested] 2+ messages in thread
* bug#62899: Performance regression in cached ‘guix shell’
2023-04-17 12:31 bug#62899: Performance regression in cached ‘guix shell’ Ludovic Courtès
@ 2023-04-17 22:53 ` Ludovic Courtès
0 siblings, 0 replies; 2+ messages in thread
From: Ludovic Courtès @ 2023-04-17 22:53 UTC (permalink / raw)
To: 62899
Ludovic Courtès <ludovic.courtes@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’.
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2023-04-17 23:32 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-04-17 12:31 bug#62899: Performance regression in cached ‘guix shell’ Ludovic Courtès
2023-04-17 22:53 ` Ludovic Courtès
Code repositories for project(s) associated with this public inbox
https://git.savannah.gnu.org/cgit/guix.git
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).