bug#19806: substitute-binary --query busy for 36 minutes with no output

bug#19806: substitute-binary --query busy for 36 minutes with no output

[Mark H Weaver]

While updating my profile with "guix package -c1 -u", "substitute-binary
--query" hung for 36 minutes with ~90% CPU utilization without any
active network connections and without printing any output.  Here was
the relevant excerpt from 'ps auxwwf' after about 30 minutes of CPU
time:

--8<---------------cut here---------------start------------->8---
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
[...]
root     23061  0.0  0.0   5804  1248 ?        Ss   12:29   0:00 /gnu/store/538qidv49w2v942502yqmv0fz187xd9z-guix-0.8.1.f1082ec/bin/guix-daemon --build-users-group guixbuild --cores=1 --max-jobs=1
root     23087 33.3  0.2  10384  4444 ?        Ss   12:30  11:44  \_ /gnu/store/538qidv49w2v942502yqmv0fz187xd9z-guix-0.8.1.f1082ec/bin/guix-daemon 23079               guixbuild --cores=1 --max-jobs=1
root     23120 87.9 58.2 1294632 1198688 ?     Sl   12:30  30:25      \_ /gnu/store/122jv790mv2mlnylbrbzav65vghbw93n-guile-2.0.11/bin/guile --no-auto-compile /gnu/store/538qidv49w2v942502yqmv0fz187xd9z-guix-0.8.1.f1082ec/bin/guix substitute-binary --query
root     23211  0.0  0.0      0     0 ?        Zs   12:30   0:00      \_ [guix] <defunct>
--8<---------------cut here---------------end--------------->8---

Looking at the nginx logs on hydra, I see that it downloaded a single
nar file (for paredit) very soon after starting up, and then didn't
download anything else from hydra until ~36 minutes later, when it
downloaded /nix-cache-info and then a narinfo file.  It then proceeded
to do several grafting operations locally.

The 'guix package' command I'm running is v0.8.1-90-g710f3ce, and the
'guix-daemon' and substitute binary is guix-0.8.1.f1082ec.

Any ideas what it was doing during those 36 silent minutes?

      Mark