Subject: bug#44053: Poor profile generation performance on spinning disks

From: Maxim Cournoyer <[email-masked]>
Date: Sat, 17 Oct 2020 23:35:45 -0400

Hello!

I've noticed on multiple occasions that using Guix on traditional
spinning drives can be quite slow.

On my home machine, will is still relying on 2 x 1 TB spinning drives in
RAID1, rebuilding my user profile, which contains 182 entries, takes on
average about 20 minutes, even when there are no packages to be built:

--8<---------------cut here---------------start------------->8--- $ time
guix package -i perl --max-jobs=1 The following package will be
upgraded: perl (dependencies or package changed)

The following derivation will be built:
   /gnu/store/lhywla1z2zcz16df4hbvvvngr9zmswr7-profile.drv

building CA certificate bundle...
building fonts directory...
generating GLib schema cache...
creating GTK+ icon theme cache...
building cache files for GTK+ input methods...
building directory of Info manuals...
building database for manual pages...
building XDG desktop file cache...
building XDG MIME database...
building profile with 182 packages...

real    19m0.126s
user    0m5.648s
sys     0m0.333s
--8<---------------cut here---------------end--------------->8---

Most of the time remains spent after the message 'building profile with
182 package...'.  That part seems IO-bound, with the spinning disks
grinding heavily and the CPU mostly idling.  The rest of the time (3
minutes), was used by the profile hooks.

The same operation on a second, more modern machine equipped with M2
SSDs does much better and takes about 1 minute to accomplish the same,
so it seems the bad performance can be mostly attributed to the much
slower disk seek times of the spinning disks.

On the older machine, two profile hooks are also sticking out w.r.t. the
time they take (they take more than one minute opposed to a few
seconds):

--8<---------------cut here---------------start------------->8---
The following profile hook will be built:
   /gnu/store/08fanpydi7z4i3qnlqbr8iz23zdgsamw-manual-database.drv
building database for manual pages...
Creating manual page database...
[2139/2139] building list of man-db entries...
175322 entries processed in 95.1 s
successfully built /gnu/store/08fanpydi7z4i3qnlqbr8iz23zdgsamw-manual-database.drv
successfully built /gnu/store/08fanpydi7z4i3qnlqbr8iz23zdgsamw-manual-database.drv
/gnu/store/wzp4mk2r7r4ysciw74gqbfkyai0zmrcc-manual-database

real    1m36.378s
user    0m1.674s
sys     0m0.108s

The following profile hook will be built:
   /gnu/store/cir84qj587i6is4akgqand7ahg9bj938-xdg-mime-database.drv
building XDG MIME database...
successfully built /gnu/store/cir84qj587i6is4akgqand7ahg9bj938-xdg-mime-database.drv
successfully built /gnu/store/cir84qj587i6is4akgqand7ahg9bj938-xdg-mime-database.drv
/gnu/store/j0bznlj2ibnhirijhnwpkkxzz4qfk8wb-xdg-mime-database

real    1m7.344s
user    0m1.331s
sys     0m0.053s
--8<---------------cut here---------------end--------------->8---

So we should profile what's going on while generating the profile (no
pun intended) and try to improve this at first since this is where most
of the time is spent on spinning drives (17 minutes out of the 20 in the
above example).

After that we could look into the two above profile hooks.

Thanks,

Maxim