Pierre Neidhardt <m...@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
