Why does setting a language in Grub take 1.5 minutes?

Why does setting a language in Grub take 1.5 minutes?

[Katherine Cox-Buday]

At some point, after a long time with no problems, my system began
taking an unreasonably long time to boot. I only reboot my system
~1/week for updates, so I never took the time to debug the problem, and
therefore, I couldn't really connect the issue with any changes that
either I or Guix had made.

I'm now trying to debug a wake from hibernate issue, and this involves a
lot of rebooting, so I had to figure this out. I have, and I'm unsure
why what I found is causing issues, and whether it's a Guix bug, or
something wrong with my setup.

Here's my partition layout:

#+begin_example
  $ lsblk
  NAME          MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINTS
  nvme0n1       259:2    0 931.5G  0 disk
  ├─nvme0n1p1   259:3    0   549M  0 part  /boot/efi
  └─nvme0n1p2   259:4    0   931G  0 part
    └─cryptroot 253:0    0   931G  0 crypt /var/lib/docker
                                           /gnu/store
                                           /
#+end_example

There are no filesystem errors.

Here's the bootloader portion of my operating-system:

#+begin_example
  (bootloader
   (bootloader-configuration
    (bootloader grub-efi-bootloader)
    (targets (list "/boot/efi"))
    (keyboard-layout keyboard-layout)))
#+end_example

Here's part of my /boot/grub/grub.cfg, generated by Guix. I've added
some echo statements to help debug.

#+begin_example
  echo "C"

  # Set 'root' to the partition that contains /gnu/store.
  search --file --set /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png
  echo "D"


  if loadfont unicode; then
    set gfxmode=auto
    insmod all_video
    echo "E"
    insmod gfxterm
    echo "F"
  fi

  terminal_output gfxterm
  echo "G"

  insmod png
  echo "H"
  if background_image /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png; then
    echo "H.1"
    set color_normal=light-gray/black
    echo "H.2"
    set color_highlight=yellow/black
    echo "H.3"
  else
    set menu_color_normal=cyan/blue
    set menu_color_highlight=white/blue
  fi
  echo "I"
  Localization configuration.
  search --file --set /gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales/en@quot.mo
  echo "J"
  set locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
  echo "K"
  set lang=en_US
  echo "L"
  insmod keylayouts
  echo "M"
  keymap /gnu/store/pgg50qzm7d2q6k0f82c43fmsxwpwrjvx-grub-keymap.us
  echo "N"
#+end_example

And here are the time elapsed between steps (at least the ones that didn't go by too quickly), in seconds:

C -> D : 13
H -> I : 13
I -> K : 27
K -> M : 157 (!!!!)
M -> N : 20

That's almost 4 minutes from unlocking the luks volume to get to the Grub menu, and then another 4 minutes to boot into the Kernel.

I then removed the keyboard configuration and changed the theme so that
it wouldn't load an image:

#+begin_example
  (bootloader
   (bootloader-configuration
    (bootloader grub-efi-bootloader)
    (targets (list "/boot/efi"))
    (theme (grub-theme
            (inherit (grub-theme))
            (image #f)))))
#+end_example

It produces a grub.cfg with this in it (again, echoes added):

#+begin_example
  echo "A"
  set locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
  echo "B"
  set lang=en_US
  echo "C"
#+end_example

Between B -> C, it still takes 157 seconds.

Does anyone know why this is taking so long or how to fix it? As it is, I'll have to manually edit my grub.cfg after every system reconfigure.

Thank you,
-- 
Katherine

Re: Why does setting a language in Grub take 1.5 minutes?

[raingloom]

On Sun, 15 May 2022 18:06:41 -0500
Katherine Cox-Buday <cox.katherine.e@gmail.com> wrote:

> At some point, after a long time with no problems, my system began
> taking an unreasonably long time to boot. I only reboot my system
> ~1/week for updates, so I never took the time to debug the problem,
> and therefore, I couldn't really connect the issue with any changes
> that either I or Guix had made.
> 
> I'm now trying to debug a wake from hibernate issue, and this
> involves a lot of rebooting, so I had to figure this out. I have, and
> I'm unsure why what I found is causing issues, and whether it's a
> Guix bug, or something wrong with my setup.
> 
> Here's my partition layout:
> 
> #+begin_example
>   $ lsblk
>   NAME          MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINTS
>   nvme0n1       259:2    0 931.5G  0 disk
>   ├─nvme0n1p1   259:3    0   549M  0 part  /boot/efi
>   └─nvme0n1p2   259:4    0   931G  0 part
>     └─cryptroot 253:0    0   931G  0 crypt /var/lib/docker
>                                            /gnu/store
>                                            /
> #+end_example
> 
> There are no filesystem errors.
> 
> Here's the bootloader portion of my operating-system:
> 
> #+begin_example
>   (bootloader
>    (bootloader-configuration
>     (bootloader grub-efi-bootloader)
>     (targets (list "/boot/efi"))
>     (keyboard-layout keyboard-layout)))
> #+end_example
> 
> Here's part of my /boot/grub/grub.cfg, generated by Guix. I've added
> some echo statements to help debug.
> 
> #+begin_example
>   echo "C"
> 
>   # Set 'root' to the partition that contains /gnu/store.
>   search --file --set
> /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png echo "D"
> 
> 
>   if loadfont unicode; then
>     set gfxmode=auto
>     insmod all_video
>     echo "E"
>     insmod gfxterm
>     echo "F"
>   fi
> 
>   terminal_output gfxterm
>   echo "G"
> 
>   insmod png
>   echo "H"
>   if background_image
> /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png; then echo
> "H.1" set color_normal=light-gray/black
>     echo "H.2"
>     set color_highlight=yellow/black
>     echo "H.3"
>   else
>     set menu_color_normal=cyan/blue
>     set menu_color_highlight=white/blue
>   fi
>   echo "I"
>   Localization configuration.
>   search --file --set
> /gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales/en@quot.mo
> echo "J" set
> locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
> echo "K" set lang=en_US
>   echo "L"
>   insmod keylayouts
>   echo "M"
>   keymap /gnu/store/pgg50qzm7d2q6k0f82c43fmsxwpwrjvx-grub-keymap.us
>   echo "N"
> #+end_example
> 
> And here are the time elapsed between steps (at least the ones that
> didn't go by too quickly), in seconds:
> 
> C -> D : 13
> H -> I : 13
> I -> K : 27
> K -> M : 157 (!!!!)
> M -> N : 20
> 
> That's almost 4 minutes from unlocking the luks volume to get to the
> Grub menu, and then another 4 minutes to boot into the Kernel.
> 
> I then removed the keyboard configuration and changed the theme so
> that it wouldn't load an image:
> 
> #+begin_example
>   (bootloader
>    (bootloader-configuration
>     (bootloader grub-efi-bootloader)
>     (targets (list "/boot/efi"))
>     (theme (grub-theme
>             (inherit (grub-theme))
>             (image #f)))))
> #+end_example
> 
> It produces a grub.cfg with this in it (again, echoes added):
> 
> #+begin_example
>   echo "A"
>   set
> locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
> echo "B" set lang=en_US
>   echo "C"
> #+end_example
> 
> Between B -> C, it still takes 157 seconds.
> 
> Does anyone know why this is taking so long or how to fix it? As it
> is, I'll have to manually edit my grub.cfg after every system
> reconfigure.
> 
> Thank you,

A guess: since LUKS seems to be involved, mayyybe it's an entropy
issue? There was a time when booting took a while on my Thinkpad
because the ssh key generations was not set up correctly or something.
A quick way to check would be to hit random keys, if it makes booting
much faster, it's probably an entropy issue.

Re: Why does setting a language in Grub take 1.5 minutes?

[Katherine Cox-Buday]

raingloom <raingloom@riseup.net> writes:

> On Sun, 15 May 2022 18:06:41 -0500
> Katherine Cox-Buday <cox.katherine.e@gmail.com> wrote:
>
>> At some point, after a long time with no problems, my system began
>> taking an unreasonably long time to boot. I only reboot my system
>> ~1/week for updates, so I never took the time to debug the problem,
>> and therefore, I couldn't really connect the issue with any changes
>> that either I or Guix had made.
>> 
>> I'm now trying to debug a wake from hibernate issue, and this
>> involves a lot of rebooting, so I had to figure this out. I have, and
>> I'm unsure why what I found is causing issues, and whether it's a
>> Guix bug, or something wrong with my setup.
>> 
>> Here's my partition layout:
>> 
>> #+begin_example
>>   $ lsblk
>>   NAME          MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINTS
>>   nvme0n1       259:2    0 931.5G  0 disk
>>   ├─nvme0n1p1   259:3    0   549M  0 part  /boot/efi
>>   └─nvme0n1p2   259:4    0   931G  0 part
>>     └─cryptroot 253:0    0   931G  0 crypt /var/lib/docker
>>                                            /gnu/store
>>                                            /
>> #+end_example
>> 
>> There are no filesystem errors.
>> 
>> Here's the bootloader portion of my operating-system:
>> 
>> #+begin_example
>>   (bootloader
>>    (bootloader-configuration
>>     (bootloader grub-efi-bootloader)
>>     (targets (list "/boot/efi"))
>>     (keyboard-layout keyboard-layout)))
>> #+end_example
>> 
>> Here's part of my /boot/grub/grub.cfg, generated by Guix. I've added
>> some echo statements to help debug.
>> 
>> #+begin_example
>>   echo "C"
>> 
>>   # Set 'root' to the partition that contains /gnu/store.
>>   search --file --set
>> /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png echo "D"
>> 
>> 
>>   if loadfont unicode; then
>>     set gfxmode=auto
>>     insmod all_video
>>     echo "E"
>>     insmod gfxterm
>>     echo "F"
>>   fi
>> 
>>   terminal_output gfxterm
>>   echo "G"
>> 
>>   insmod png
>>   echo "H"
>>   if background_image
>> /gnu/store/9lcbyg3pkb38chhv0yzk6hn3arxfjfgk-grub-image.png; then echo
>> "H.1" set color_normal=light-gray/black
>>     echo "H.2"
>>     set color_highlight=yellow/black
>>     echo "H.3"
>>   else
>>     set menu_color_normal=cyan/blue
>>     set menu_color_highlight=white/blue
>>   fi
>>   echo "I"
>>   Localization configuration.
>>   search --file --set
>> /gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales/en@quot.mo
>> echo "J" set
>> locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
>> echo "K" set lang=en_US
>>   echo "L"
>>   insmod keylayouts
>>   echo "M"
>>   keymap /gnu/store/pgg50qzm7d2q6k0f82c43fmsxwpwrjvx-grub-keymap.us
>>   echo "N"
>> #+end_example
>> 
>> And here are the time elapsed between steps (at least the ones that
>> didn't go by too quickly), in seconds:
>> 
>> C -> D : 13
>> H -> I : 13
>> I -> K : 27
>> K -> M : 157 (!!!!)
>> M -> N : 20
>> 
>> That's almost 4 minutes from unlocking the luks volume to get to the
>> Grub menu, and then another 4 minutes to boot into the Kernel.
>> 
>> I then removed the keyboard configuration and changed the theme so
>> that it wouldn't load an image:
>> 
>> #+begin_example
>>   (bootloader
>>    (bootloader-configuration
>>     (bootloader grub-efi-bootloader)
>>     (targets (list "/boot/efi"))
>>     (theme (grub-theme
>>             (inherit (grub-theme))
>>             (image #f)))))
>> #+end_example
>> 
>> It produces a grub.cfg with this in it (again, echoes added):
>> 
>> #+begin_example
>>   echo "A"
>>   set
>> locale_dir=/gnu/store/mdrdpd6aw9ikx1wzx6ljydpzvnvwpq0y-grub-locales
>> echo "B" set lang=en_US
>>   echo "C"
>> #+end_example
>> 
>> Between B -> C, it still takes 157 seconds.
>> 
>> Does anyone know why this is taking so long or how to fix it? As it
>> is, I'll have to manually edit my grub.cfg after every system
>> reconfigure.
>> 
>> Thank you,
>
> A guess: since LUKS seems to be involved, mayyybe it's an entropy
> issue? There was a time when booting took a while on my Thinkpad
> because the ssh key generations was not set up correctly or something.

Do you recall any more details? I'm struggling to think of how ssh key
generation would impact startup? Unless you meant they both had the same
symptom which led you to look into entropy?

When I first started investigating, my first guess was something related
to LUKS too, but it actually unlocks the drive pretty quickly, which is
why I began investigating the steps in Grub.

Also, I'm not very familiar with LUKS, but doesn't it only use Linux's
random facilities for key generation? I didn't think it used it to
unlock or decrypt.

There are also some comments[1] in Guix's grub code suggesting that
traversing the store is an expensive operation. I'm not sure why this
is, since it's pointing to pretty specific files.

If this is the case, I wanted to open an issue to determine what it is
about configurations like mine that make booting take so long (I assume
everyone would be complaining if this was more prevalent), and if it's
something we can avoid, explore alternative grub.cfg generation to
mitigate the problem.

> A quick way to check would be to hit random keys, if it makes booting
> much faster, it's probably an entropy issue.

I kind of doubt this is it. Linux generates entropy from mouse movement
too, doesn't it? When I play games on this machine, it involves a lot of
mouse movement, and it hasn't ever seemed to impact the time it's taken
to boot. And actually, once the boot time got worse, it never really
changed after that, for better or for worse. Still, I'm often wrong, so
I'll try it!

[1] - https://git.savannah.gnu.org/cgit/guix.git/tree/gnu/bootloader/grub.scm?h=master#n454

Thank you!
-- 
Katherine

Re: Why does setting a language in Grub take 1.5 minutes?

[Olivier Dion via]

On Sun, 15 May 2022, Katherine Cox-Buday <cox.katherine.e@gmail.com> wrote:
> At some point, after a long time with no problems, my system began
> taking an unreasonably long time to boot. I only reboot my system
> ~1/week for updates, so I never took the time to debug the problem, and
> therefore, I couldn't really connect the issue with any changes that
> either I or Guix had made.

I've come across this
https://lists.gnu.org/archive/html/grub-devel/2022-05/msg00005.html
today.  If it is the problem, perhaps GCing your old kernels would make
the boot faster.

-- 
Olivier Dion
oldiob.dev

Re: Why does setting a language in Grub take 1.5 minutes?

[Katherine Cox-Buday]

Olivier Dion <olivier.dion@polymtl.ca> writes:

> On Sun, 15 May 2022, Katherine Cox-Buday <cox.katherine.e@gmail.com> wrote:
>> At some point, after a long time with no problems, my system began
>> taking an unreasonably long time to boot. I only reboot my system
>> ~1/week for updates, so I never took the time to debug the problem,
>> and therefore, I couldn't really connect the issue with any changes
>> that either I or Guix had made.
>
> I've come across this
> https://lists.gnu.org/archive/html/grub-devel/2022-05/msg00005.html
> today. If it is the problem, perhaps GCing your old kernels would make
> the boot faster.

Thank you for responding.

I think this only impacts running `grub-mkconfig` and not booting, doesn't it? Aside from that, the echo statements I gave suggest that the issue is with setting the language.

Still, I removed some old generations of my system. Things went a little faster, but I'm guessing that's probably a side-effect of shrinking my /gnu/store path.

Thank you for the suggestion.
-- 
Katherine