bug#36509: guix pull: too many substitute updates, or bad log messages

bug#36509: guix pull: too many substitute updates, or bad log messages

[Robert Vollmert]

When running `guix pull`, output like the following is common
for me:

$ guix pull
Updating channel 'puzzlink' from Git repository at '/home/rob/guix-puzzlink'…
[…]
Building from these channels:
  guix      https://github.com/robx/guix.git	11f68b3
[…]
Computing Guix derivation for 'x86_64-linux'... |
The following derivations will be built:
   /gnu/store/ym0l8rvnh3aa3qv8g3xgh1mszbhww8c2-elm.drv
[…]
   /gnu/store/dcxwfh37bn8r3h8s9w7wfq8yhzynqxx5-profile.drv
The following profile hooks will be built:
   /gnu/store/biw1n2a956skpaa4m7rmka6j8h1clhmv-guix-package-cache.drv
[…]
   /gnu/store/kxrkynck33ypwyy09ypi2qm7737fsw28-fonts-dir.drv
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
building /gnu/store/wxfi8mdp11l5k4ngkbsy9apcg9h74jfk-guix-system.drv…

Either guix is making useless extra downloads or:

(a) the substitute log message should be changed to differentiate between
the different calls
(b) there should be extra log messages before the substitute messages to
indicate what guix is doing that causes the individual substitue messages.

bug#36509: guix pull: too many substitute updates, or bad log messages

[Ludovic Courtès]

Hi,

Robert Vollmert <rob@vllmrt.net> skribis:

> When running `guix pull`, output like the following is common
> for me:
>
> $ guix pull
> Updating channel 'puzzlink' from Git repository at '/home/rob/guix-puzzlink'…
> […]
> Building from these channels:
>   guix      https://github.com/robx/guix.git	11f68b3
> […]
> Computing Guix derivation for 'x86_64-linux'... |
> The following derivations will be built:
>    /gnu/store/ym0l8rvnh3aa3qv8g3xgh1mszbhww8c2-elm.drv
> […]
>    /gnu/store/dcxwfh37bn8r3h8s9w7wfq8yhzynqxx5-profile.drv
> The following profile hooks will be built:
>    /gnu/store/biw1n2a956skpaa4m7rmka6j8h1clhmv-guix-package-cache.drv
> […]
>    /gnu/store/kxrkynck33ypwyy09ypi2qm7737fsw28-fonts-dir.drv
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> building /gnu/store/wxfi8mdp11l5k4ngkbsy9apcg9h74jfk-guix-system.drv…

I believe this is fixed by 9b9b753529db1c7a8c4628cc255e358703c15618.

The story here is that we were calling ‘show-what-to-build’ with
#:use-substitutes #f.  Thus, Guix would not try to see which substitutes
are available (and it’d report that everything must be built.)

But right after that, we’d build the profile with substitutes enabled,
and at that point it would have to fetch substitute info (“narinfos”)
for each of these, more or less one at a time (because ‘guix substitute
--substitute’ is called once for each store item.)

IOW, ‘show-what-to-build’ warms the substitute info cache as a
side-effect, and that cache warm-up was not happening here.

Thanks,
Ludo’.