[bug#50040] [PATCH 0/2] publish: Always render nar/narinfo during backing.

["Ludovic Courtès" <ludo@gnu.org>]

Hi Mathieu,

An additional data point: while stracing ‘guix publish’ on berlin just
now, I saw read(2) calls taking several seconds (!) to complete:

--8<---------------cut here---------------start------------->8---
14:22:07 openat(AT_FDCWD, "/var/cache/guix/publish/hashes/wcd9bci97i2zi52ay4vddvr1jx9w50kz", O_RDONLY) = 33 <0.000032>
14:22:07 fstat(33, {st_mode=S_IFREG|0666, st_size=60, ...}) = 0 <0.000007>
14:22:07 lseek(33, 0, SEEK_CUR)         = 0 <0.000006>
14:22:07 read(33, "/gnu/store/wcd9bci97i2zi52ay4vdd"..., 4096) = 60 <2.540400>
14:22:10 read(33, "", 4096)             = 0 <0.000014>
14:22:10 close(33)                      = 0 <0.000008>
--8<---------------cut here---------------end--------------->8---

The load is indeed high right now:

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ uptime
 14:24:18  up 265 days 21:09,  1 user,  load average: 10.61, 8.42, 8.00
--8<---------------cut here---------------end--------------->8---

There are a few ongoing builds, which could partly explain the high load
(‘guix-daemon’ shows up at the top in iotop):

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo guix processes|grep -C3 LockHeld
SessionPID: 43868
ClientPID: 43515
ClientCommand: /gnu/store/6l9rix46ydxyldf74dvpgr60rf5ily0c-guile-3.0.7/bin/guile --no-auto-compile /gnu/store/7rqj61dy660k0nw97w7657zbxnbdvg1g-update-guix.gnu.org
LockHeld: /gnu/store/srim97jxlxgyiday0j3hbq2z0w03iy3k-guix-web-site.lock
ChildPID: 49648
ChildCommand: : /gnu/store/p9di786py35m4kxszf466wcla6jvq96h-guix-1.3.0-3.50dfbbf/libexec/guix/guile \ /gnu/store/p9di786py35m4kxszf466wcla6jvq96h-guix-1.3.0-3.50dfbbf/bin/guix substitute --query

--
SessionPID: 61372
ClientPID: 58620
ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrpvrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=cuirass host=/tmp 14259
LockHeld: /gnu/store/xdvzddg84by15s1c17k543b39c03jp8i-isl-0.23.drv.lock

SessionPID: 61373
ClientPID: 58620
ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrpvrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=cuirass host=/tmp 14259
LockHeld: /gnu/store/2wm7b9g07nxxhrnfcggw6ibdry65fpwb-xfce4-panel-4.16.3-builder.lock

SessionPID: 61374
ClientPID: 58620
ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrpvrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=cuirass host=/tmp 14259
LockHeld: /gnu/store/1jmidz4i70w3lczn99wgn19dksb0pzhv-pkg-config-0.29.2-builder.lock

SessionPID: 61375
ClientPID: 58620
ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrpvrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=cuirass host=/tmp 14259
LockHeld: /gnu/store/4j7s86xp7w5jgm84lr18szln1zpw36zd-static-binaries-tarball-0.drv.lock
--8<---------------cut here---------------end--------------->8---

The ‘mumi worker’ process also seems to be doing a lot of I/O and using
quite a bit of CPU (presumably allocating a lot).  Its ‘perf’ profile is
like this:

--8<---------------cut here---------------start------------->8---
   2.62%  .mumi-real  libguile-3.0.so.1.1.1  [.] scm_ilength
   1.20%  .mumi-real  libguile-3.0.so.1.1.1  [.] scm_getc
   1.12%  .mumi-real  libgc.so.1.4.3         [.] GC_add_to_black_list_normal.part.4
   1.06%  .mumi-real  libgc.so.1.4.3         [.] GC_build_fl
   0.98%  .mumi-real  libgc.so.1.4.3         [.] GC_reclaim_clear
   0.97%  .mumi-real  libguile-3.0.so.1.1.1  [.] get_callee_vcode
   0.91%  .mumi-real  libgc.so.1.4.3         [.] GC_generic_malloc_many
   0.90%  .mumi-real  libguile-3.0.so.1.1.1  [.] peek_byte_or_eof
   0.78%  .mumi-real  [JIT] tid 62601        [.] 0x00007f886964804d
--8<---------------cut here---------------end--------------->8---

Food for thought…

Ludo’.