Re: guix environment --profile with --ad-hoc

[Ricardo Wurmus <rekado@elephly.net>]

Pierre Neidhardt <mail@ambrevar.xyz> writes:

> It seems to be some thing more than just Guix commands being slow.
> On my machine
>
>
> --8<---------------cut here---------------start------------->8---
> $ time guix environment --help >/dev/null
>
> real	0m0.345s
> --8<---------------cut here---------------end--------------->8---
>
> Which is 2s less than
>
> --8<---------------cut here---------------start------------->8---
> $ time guix environment --profile=/my/profile -- exit
>
> real	0m2.372s
> --8<---------------cut here---------------end--------------->8---
>
> So `guix environment --profile' seems to be pretty slow still.

https://elephly.net/downies/guix-env-perf.svg is a timechart recording
of “guix environment --profile=$HOME/.guix-profile -- exit”.  It shows
that 0.5s Guix is busy with itself, and then enters a back and forth
with the daemon.  The little thing at the end is where “exit” is invoked
(and fails).

strace reveals more.  For example, some time is lost searching libraries
and other files.  (At least the excessive library searches should
already have been mitigated by changes on the core-updates branch.)
This includes reading .go files, .scm files, reading TLS certs for
guile-gnutls, etc.

Then we finally connect to the daemon.  We read the profile manifest,
and then go on another search for Guile files, this time related to
package modules.  For every module it looks something like this:

--8<---------------cut here---------------start------------->8---
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/gnu/packages/commencement.scm", 0x7ffdcfe812e0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/gnu/packages/commencement.scm", 0x7ffdcfe812e0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/gnu/packages/commencement.scm", 0x7ffdcfe812e0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/gnu/packages/commencement.scm", 0x7ffdcfe812e0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/commencement.scm", {st_mode=S_IFREG|0644, st_size=159995, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/lib/guile/3.0/ccache/gnu/packages/commencement.go", 0x7ffdcfe810f0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/lib/guile/3.0/site-ccache/gnu/packages/commencement.go", 0x7ffdcfe810f0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/commencement.go", {st_mode=S_IFREG|0644, st_size=727379, ...}) = 0
6455  openat(AT_FDCWD, "/home/rekado/dev/gx/branches/master/gnu/packages/commencement.go", O_RDONLY|O_CLOEXEC) = 14
--8<---------------cut here---------------end--------------->8---

I’m guessing that we could avoid some of that searching (and thus
condense a whole lot of stat calls) by constraining things a little
ahead of time.  We know the location of Guile modules in advance, so
perhaps we can come up with a way to avoid having to go on
GUILE_LOAD_PATH and GUILE_LOAD_COMPILED_PATH for everything, e.g. by
recording GUIX_ROOT and using that.

Same for patches:

--8<---------------cut here---------------start------------->8---
…
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/binutils-boot-2.20.1a.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/binutils-boot-2.20.1a.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/binutils-boot-2.20.1a.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/binutils-boot-2.20.1a.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/patches/binutils-boot-2.20.1a.patch", {st_mode=S_IFREG|0644, st_size=6924, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/glibc-boot-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/glibc-boot-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/glibc-boot-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/glibc-boot-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/patches/glibc-boot-2.16.0.patch", {st_mode=S_IFREG|0644, st_size=13079, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/glibc-bootstrap-system-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/glibc-bootstrap-system-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/glibc-bootstrap-system-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/glibc-bootstrap-system-2.16.0.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/patches/glibc-bootstrap-system-2.16.0.patch", {st_mode=S_IFREG|0644, st_size=951, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/gcc-4.9-libsanitizer-fix.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/gcc-4.9-libsanitizer-fix.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/gcc-4.9-libsanitizer-fix.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/gcc-4.9-libsanitizer-fix.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/patches/gcc-4.9-libsanitizer-fix.patch", {st_mode=S_IFREG|0644, st_size=3291, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/gcc-4.9-libsanitizer-ustat.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/gcc-4.9-libsanitizer-ustat.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/gcc-4.9-libsanitizer-ustat.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/gcc-4.9-libsanitizer-ustat.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/home/rekado/dev/gx/branches/master/gnu/packages/patches/gcc-4.9-libsanitizer-ustat.patch", {st_mode=S_IFREG|0644, st_size=1473, ...}) = 0
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/3.0/gcc-4.9-libsanitizer-mode-size.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/3.0/gcc-4.9-libsanitizer-mode-size.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/site/gcc-4.9-libsanitizer-mode-size.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
6455  stat("/gnu/store/m5iprcg6pb5ch86r9agmqwd8v6kp7999-guile-3.0.5/share/guile/gcc-4.9-libsanitizer-mode-size.patch", 0x7ffdcfe80ef0) = -1 ENOENT (No such file or directory)
…
--8<---------------cut here---------------end--------------->8---

But this is still all rather benign.  The real slow-down is due to
talking to the daemon.  I’m not sure I understand all the strace output,
but it looks like we read file names from the daemon socket and then
write the contents of the builders and derivations for these files back
to the daemon socket.

It’s not clear to me if Guix computes these builders and derivations
from scratch and then sends them over the socket, or if it reads them
from files and sends them over.  But it does seem like perhaps we could
avoid some of the work, or at least some of the socket communication
when the daemon could read existing files directly.

In between we see again and again stat’ing of Scheme source files, that
are always first searched for in Guile’s output directory, of course in
vain.

It does this for all nodes in the graph, sources files, builders,
derivations, etc.  Lots of work.

So it’s not unsurprising that it takes longer than “guix environment
--help”, which doesn’t have to talk to the daemon at all.  The question
is just if we can avoid some of that work and if so how much of it.

-- 
Ricardo