Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.user > #204301 > unrolled thread

Slow boot

Back to article view | Back to linux.debian.user

Contents

  Slow boot Richard Hector <richard@walnut.gen.nz> - 2019-01-11 02:10 +0100
    Re: Slow boot Felix Miata <mrmazda@earthlink.net> - 2019-01-11 03:30 +0100
      Re: Slow boot Richard Hector <richard@walnut.gen.nz> - 2019-01-11 05:00 +0100
        Re: Slow boot Felix Miata <mrmazda@earthlink.net> - 2019-01-11 07:50 +0100
        Re: Slow boot Curt <curty@free.fr> - 2019-01-11 09:50 +0100
    Re: Slow boot Dan Ritter <dsr@randomstring.org> - 2019-01-11 13:00 +0100
      Re: Slow boot Cindy-Sue Causey <butterflybytes@gmail.com> - 2019-01-11 13:20 +0100
        Re: Slow boot Dan Ritter <dsr@randomstring.org> - 2019-01-11 14:40 +0100
          Re: Slow boot Cindy-Sue Causey <butterflybytes@gmail.com> - 2019-01-11 23:00 +0100
    Re: Slow boot David <bouncingcats@gmail.com> - 2019-01-11 13:30 +0100
      Re: Slow boot deloptes <deloptes@gmail.com> - 2019-01-11 17:20 +0100
      Re: Slow boot Richard Hector <richard@walnut.gen.nz> - 2019-01-12 04:50 +0100
        Re: Slow boot Richard Hector <richard@walnut.gen.nz> - 2019-01-12 05:30 +0100
    Re: Slow boot David <bouncingcats@gmail.com> - 2019-01-11 13:40 +0100
    Re: Slow boot Michael Stone <mstone@debian.org> - 2019-01-11 15:50 +0100
      Re: Slow boot Richard Hector <richard@walnut.gen.nz> - 2019-01-12 04:50 +0100

#204301 — Slow boot

[Multipart message — attachments visible in raw view] — view raw

Hi all,

This machine is taking ages to boot.

It's a fresh install.

According to dmesg, this is where it appears to hang:

[    2.717311] device-mapper: uevent: version 1.0.3
[    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
initialised: dm-d
evel@redhat.com
[    2.978281] clocksource: Switched to clocksource tsc
[  121.459392] md: linear personality registered for level -1
[  121.460391] md: multipath personality registered for level -4
[  121.461444] md: raid0 personality registered for level 0

I have started wondering recently about the hardware - could I have a
clock problem?

None of the other 'clocksource' entries have a similar lag, and there's
no similar lag at that point on my desktop.

Do I need to provide more context, or do more diagnostics?

Thanks,
Richard

[toc] | [next] | [standalone]

#204303

Richard Hector composed on 2019-01-11 14:03 (UTC+1300):

> This machine is taking ages to boot.

> It's a fresh install.

> According to dmesg, this is where it appears to hang:

> [    2.717311] device-mapper: uevent: version 1.0.3
> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
> initialised: dm-d
> evel@redhat.com
> [    2.978281] clocksource: Switched to clocksource tsc
> [  121.459392] md: linear personality registered for level -1
> [  121.460391] md: multipath personality registered for level -4
> [  121.461444] md: raid0 personality registered for level 0

> I have started wondering recently about the hardware - could I have a
> clock problem?

> None of the other 'clocksource' entries have a similar lag, and there's
> no similar lag at that point on my desktop.

> Do I need to provide more context, or do more diagnostics?

Possibly kernel-parameters.txt has a clock suggestion, maybe

	clocksource=hpet

or forcing tsc from cmdline would switch to it at a more opportune time?
-- 
Evolution as taught in public schools is religion, not science.

 Team OS/2 ** Reg. Linux User #211409 ** a11y rocks!

Felix Miata  ***  http://fm.no-ip.com/

[toc] | [prev] | [next] | [standalone]

#204304

[Multipart message — attachments visible in raw view] — view raw

On 11/01/19 3:27 PM, Felix Miata wrote:
> Richard Hector composed on 2019-01-11 14:03 (UTC+1300):
> 
>> This machine is taking ages to boot.
> 
>> It's a fresh install.
> 
>> According to dmesg, this is where it appears to hang:
> 
>> [    2.717311] device-mapper: uevent: version 1.0.3
>> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
>> initialised: dm-d
>> evel@redhat.com
>> [    2.978281] clocksource: Switched to clocksource tsc
>> [  121.459392] md: linear personality registered for level -1
>> [  121.460391] md: multipath personality registered for level -4
>> [  121.461444] md: raid0 personality registered for level 0
> 
>> I have started wondering recently about the hardware - could I have a
>> clock problem?
> 
>> None of the other 'clocksource' entries have a similar lag, and there's
>> no similar lag at that point on my desktop.
> 
>> Do I need to provide more context, or do more diagnostics?
> 
> Possibly kernel-parameters.txt has a clock suggestion, maybe
> 
> 	clocksource=hpet
> 
> or forcing tsc from cmdline would switch to it at a more opportune time?
> 

Thanks Felix.

Well that's interesting - if I put clocksource=hpet on the kernel
command line, it still pauses at the same place, but the clocksource
message isn't there - which seems to me to eliminate it as the source of
the problem. (when I use clocksource=tsc, that line does appear as before)

But then I also got rid of those md messages by blacklisting the
modules, so now I have different messages both sides of the hang.

So either there's something else unlogged happening between, or there's
parallelism happening. Either way, I'm not sure where to look next :-(

Hints on where to look for the boot sequence in the kernel source, perhaps?

Cheers,
Richard

[toc] | [prev] | [next] | [standalone]

#204305

Richard Hector composed on 2019-01-11 16:54 (UTC+1300):
...
> So either there's something else unlogged happening between, or there's
> parallelism happening. Either way, I'm not sure where to look next :-(

> Hints on where to look for the boot sequence in the kernel source, perhaps?

Maybe pastebinit a bigger hunk of dmesg, or journal. Journal commonly has clues not found in dmesg.
-- 
Evolution as taught in public schools is religion, not science.

 Team OS/2 ** Reg. Linux User #211409 ** a11y rocks!

Felix Miata  ***  http://fm.no-ip.com/

[toc] | [prev] | [next] | [standalone]

#204308

On 2019-01-11, Richard Hector <richard@walnut.gen.nz> wrote:
>
> Hints on where to look for the boot sequence in the kernel source, perhap=
> s?
>

If you're using systemd the output of

 systemd-analyze blame
 systemd-analyze critical-chain

might be informative.

[toc] | [prev] | [next] | [standalone]

#204310

Richard Hector wrote: 
> Hi all,
> 
> This machine is taking ages to boot.
> 
> It's a fresh install.
> 
> According to dmesg, this is where it appears to hang:
> 
> [    2.717311] device-mapper: uevent: version 1.0.3
> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
> initialised: dm-d
> evel@redhat.com
> [    2.978281] clocksource: Switched to clocksource tsc
> [  121.459392] md: linear personality registered for level -1
> [  121.460391] md: multipath personality registered for level -4
> [  121.461444] md: raid0 personality registered for level 0
> 
> I have started wondering recently about the hardware - could I have a
> clock problem?
> 
> None of the other 'clocksource' entries have a similar lag, and there's
> no similar lag at that point on my desktop.
> 
> Do I need to provide more context, or do more diagnostics?
> 

As an experiment -- try this:

echo udev_log=\"err\" >> /etc/udev/udev.conf

(Or, alternatively, edit /etc/udef/udev.conf and insert/change
that as necessary.)

-dsr-

[toc] | [prev] | [next] | [standalone]

#204311

On 1/11/19, Dan Ritter <dsr@randomstring.org> wrote:
> Richard Hector wrote:
>> Hi all,
>>
>> This machine is taking ages to boot.
>>
>> It's a fresh install.
>>
>> According to dmesg, this is where it appears to hang:
>>
>> [    2.717311] device-mapper: uevent: version 1.0.3
>> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
>> initialised: dm-d
>> evel@redhat.com
>> [    2.978281] clocksource: Switched to clocksource tsc
>> [  121.459392] md: linear personality registered for level -1
>> [  121.460391] md: multipath personality registered for level -4
>> [  121.461444] md: raid0 personality registered for level 0
>>
>> I have started wondering recently about the hardware - could I have a
>> clock problem?
>>
>> None of the other 'clocksource' entries have a similar lag, and there's
>> no similar lag at that point on my desktop.
>>
>> Do I need to provide more context, or do more diagnostics?
>>
>
> As an experiment -- try this:
>
> echo udev_log=\"err\" >> /etc/udev/udev.conf
>
> (Or, alternatively, edit /etc/udef/udev.conf and insert/change
> that as necessary.)


Manually editing sounds like a good route because mine says this when
you get there:

# udevd is started in the initramfs, so when this file is modified the
# initramfs should be rebuilt.

"[S]hould"... Sounds like some of that should/shall/will.... and must
(??) coming into play.

Cindy :)
-- 
Cindy-Sue Causey
Talking Rock, Pickens County, Georgia, USA

* runs with birdseed *

[toc] | [prev] | [next] | [standalone]

#204315

Cindy-Sue Causey wrote: 
> On 1/11/19, Dan Ritter <dsr@randomstring.org> wrote:
> > Richard Hector wrote:
> >> Hi all,
> >>
> >> This machine is taking ages to boot.
> >>
> >> It's a fresh install.
> >>
> >> According to dmesg, this is where it appears to hang:
> >>
> >> [    2.717311] device-mapper: uevent: version 1.0.3
> >> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
> >> initialised: dm-d
> >> evel@redhat.com
> >> [    2.978281] clocksource: Switched to clocksource tsc
> >> [  121.459392] md: linear personality registered for level -1
> >> [  121.460391] md: multipath personality registered for level -4
> >> [  121.461444] md: raid0 personality registered for level 0
> >>
> >> I have started wondering recently about the hardware - could I have a
> >> clock problem?
> >>
> >> None of the other 'clocksource' entries have a similar lag, and there's
> >> no similar lag at that point on my desktop.
> >>
> >> Do I need to provide more context, or do more diagnostics?
> >>
> >
> > As an experiment -- try this:
> >
> > echo udev_log=\"err\" >> /etc/udev/udev.conf
> >
> > (Or, alternatively, edit /etc/udef/udev.conf and insert/change
> > that as necessary.)
> 
> 
> Manually editing sounds like a good route because mine says this when
> you get there:
> 
> # udevd is started in the initramfs, so when this file is modified the
> # initramfs should be rebuilt.
> 
> "[S]hould"... Sounds like some of that should/shall/will.... and must
> (??) coming into play.

Yes, it needs to be followed by running:

# update-initramfs -k all -u

or similar. Thanks for the catch!

-dsr-

[toc] | [prev] | [next] | [standalone]

#204328

On 1/11/19, Dan Ritter <dsr@randomstring.org> wrote:
> Cindy-Sue Causey wrote:
>> On 1/11/19, Dan Ritter <dsr@randomstring.org> wrote:
>> >
>> > As an experiment -- try this:
>> >
>> > echo udev_log=\"err\" >> /etc/udev/udev.conf
>> >
>> > (Or, alternatively, edit /etc/udef/udev.conf and insert/change
>> > that as necessary.)
>>
>>
>> Manually editing sounds like a good route because mine says this when
>> you get there:
>>
>> # udevd is started in the initramfs, so when this file is modified the
>> # initramfs should be rebuilt.
>>
>> "[S]hould"... Sounds like some of that should/shall/will.... and must
>> (??) coming into play.
>
> Yes, it needs to be followed by running:
>
> # update-initramfs -k all -u
>
> or similar. Thanks for the catch!


You're welcome. It was a nice side bonus from lurking along from the
sidelines. Having read that, it occurred to me that it would be
interesting to:

1) Enter that change but don't update then monitor appropriate files
for short period of time.

2) Next update initramfs then monitor those files again.

3) DELETE that change but do NOT update initramfs then monitor same files again.

4) Lastly update initramfs over that deletion then monitor one last
time to see what, if anything, changes.

I'm a-suming it would possibly/likely turn out similar to how we
*must* run update-grub after making changes to /etc/grub.d... if we
would like to see our manual changes do anything useful, that is. :)

PS This is one of those cases that falls under a different thread...
that one (or more) about personalized tweaks under locations other
than /home/user. I'm imagining this kind of tweak possibly getting
zapped on the next upgrade that includes /etc/udef/udev.conf.

Cindy :)
-- 
Cindy-Sue Causey
Talking Rock, Pickens County, Georgia, USA

* runs with birdseed *

[toc] | [prev] | [next] | [standalone]

#204313

On Fri, 11 Jan 2019 at 12:04, Richard Hector <richard@walnut.gen.nz> wrote:
>
> Hi all,
>
> This machine is taking ages to boot.
>
> It's a fresh install.
>
> According to dmesg, this is where it appears to hang:
>
> [    2.717311] device-mapper: uevent: version 1.0.3
> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
> initialised: dm-d
> evel@redhat.com
> [    2.978281] clocksource: Switched to clocksource tsc
> [  121.459392] md: linear personality registered for level -1
> [  121.460391] md: multipath personality registered for level -4
> [  121.461444] md: raid0 personality registered for level 0

Hi, I have no expertise in this, except to suggest that if I was
seeing your symptoms then I would investigate if the discussion
here might be relevant:
https://lists.debian.org/debian-devel/2018/12/msg00184.html

[toc] | [prev] | [next] | [standalone]

#204320

David wrote:

> Hi, I have no expertise in this, except to suggest that if I was
> seeing your symptoms then I would investigate if the discussion
> here might be relevant:
> https://lists.debian.org/debian-devel/2018/12/msg00184.html

Good story - thanks and no comments!

[toc] | [prev] | [next] | [standalone]

#204335

[Multipart message — attachments visible in raw view] — view raw

On 12/01/19 1:28 AM, David wrote:
> Hi, I have no expertise in this, except to suggest that if I was
> seeing your symptoms then I would investigate if the discussion
> here might be relevant:
> https://lists.debian.org/debian-devel/2018/12/msg00184.html

Interesting, thanks - I'm going to try 4.19 from backports, so that I
can try the random.trust_cpu option mentioned in that thread.

Richard

[toc] | [prev] | [next] | [standalone]

#204337

[Multipart message — attachments visible in raw view] — view raw

On 12/01/19 4:47 PM, Richard Hector wrote:
> On 12/01/19 1:28 AM, David wrote:
>> Hi, I have no expertise in this, except to suggest that if I was
>> seeing your symptoms then I would investigate if the discussion
>> here might be relevant:
>> https://lists.debian.org/debian-devel/2018/12/msg00184.html
> 
> Interesting, thanks - I'm going to try 4.19 from backports, so that I
> can try the random.trust_cpu option mentioned in that thread.

Well - not as informative as I'd hoped - the new kernel doesn't have
that delay (well, there seems to be a 20s delay in a similar place), so
trying the random.trust_cpu option wasn't so useful. I did anyway, and
the 20s delay remained - but it's not really apparent during the boot,
so maybe I was wrong and user-mode processes have started by then.

I guess I'll just keep using the 4.19 kernel anyway ...

Richard

[toc] | [prev] | [next] | [standalone]

#204314

On Fri, 11 Jan 2019 at 12:04, Richard Hector <richard@walnut.gen.nz> wrote:
>
> This machine is taking ages to boot.

You could also try the 'systemd-analyze blame' tool.

[toc] | [prev] | [next] | [standalone]

#204317

On Fri, Jan 11, 2019 at 02:03:44PM +1300, Richard Hector wrote:
>According to dmesg, this is where it appears to hang:
>
>[    2.717311] device-mapper: uevent: version 1.0.3
>[    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
>initialised: dm-d
>evel@redhat.com
>[    2.978281] clocksource: Switched to clocksource tsc
>[  121.459392] md: linear personality registered for level -1
>[  121.460391] md: multipath personality registered for level -4
>[  121.461444] md: raid0 personality registered for level 0

dmesg is the wrong tool for this, as it only shows kernel messages and 
the delay is probably not in the kernel. try "journalctl -b", which will 
show both kernel messages and other logs for the current boot.

[toc] | [prev] | [next] | [standalone]

#204336

[Multipart message — attachments visible in raw view] — view raw

On 12/01/19 3:41 AM, Michael Stone wrote:
> On Fri, Jan 11, 2019 at 02:03:44PM +1300, Richard Hector wrote:
>> According to dmesg, this is where it appears to hang:
>>
>> [    2.717311] device-mapper: uevent: version 1.0.3
>> [    2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
>> initialised: dm-d
>> evel@redhat.com
>> [    2.978281] clocksource: Switched to clocksource tsc
>> [  121.459392] md: linear personality registered for level -1
>> [  121.460391] md: multipath personality registered for level -4
>> [  121.461444] md: raid0 personality registered for level 0
> 
> dmesg is the wrong tool for this, as it only shows kernel messages and
> the delay is probably not in the kernel. try "journalctl -b", which will
> show both kernel messages and other logs for the current boot.
> 

I think it is in the kernel, actually. Compare:

dmesg:

[    2.655799] random: crng init done
[    2.655828] random: 7 urandom warning(s) missed due to ratelimiting
[    2.666315] md8: detected capacity change from 0 to 499965231104
[    2.839576] device-mapper: uevent: version 1.0.3
[    2.839664] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23)
initialised: dm-devel@redhat.com
[    2.979835] clocksource: Switched to clocksource tsc
[  131.281666] PM: Starting manual resume from disk
[  131.281699] PM: Hibernation image partition 253:8 present
[  131.281699] PM: Looking for hibernation image.
[  131.281783] PM: Image not found (code -22)
[  131.281784] PM: Hibernation image not present or could not be loaded.
[  141.617008] EXT4-fs (md0): mounted filesystem with ordered data mode.
Opts: (null)
[  172.514409] ip_tables: (C) 2000-2006 Netfilter Core Team
[  172.556027] systemd[1]: systemd 232 running in system mode. (+PAM
+AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[  172.556181] systemd[1]: Detected architecture x86-64.

journalctl -b:

Jan 12 16:12:37 rh-khost1 kernel: random: crng init done
Jan 12 16:12:37 rh-khost1 kernel: random: 7 urandom warning(s) missed
due to ratelimiting
Jan 12 16:12:37 rh-khost1 kernel: md8: detected capacity change from 0
to 499965231104
Jan 12 16:12:37 rh-khost1 kernel: device-mapper: uevent: version 1.0.3
Jan 12 16:12:37 rh-khost1 kernel: device-mapper: ioctl: 4.35.0-ioctl
(2016-06-23) initialised: dm-devel@redhat.com
Jan 12 16:12:37 rh-khost1 kernel: clocksource: Switched to clocksource tsc
Jan 12 16:12:37 rh-khost1 kernel: PM: Starting manual resume from disk
Jan 12 16:12:37 rh-khost1 kernel: PM: Hibernation image partition 253:8
present
Jan 12 16:12:37 rh-khost1 kernel: PM: Looking for hibernation image.
Jan 12 16:12:37 rh-khost1 kernel: PM: Image not found (code -22)
Jan 12 16:12:37 rh-khost1 kernel: PM: Hibernation image not present or
could not be loaded.
Jan 12 16:12:37 rh-khost1 kernel: EXT4-fs (md0): mounted filesystem with
ordered data mode. Opts: (null)
Jan 12 16:12:37 rh-khost1 kernel: ip_tables: (C) 2000-2006 Netfilter
Core Team
Jan 12 16:12:37 rh-khost1 systemd[1]: systemd 232 running in system
mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP
+LIBCRYPTSETUP +GCRYPT +GNUTLS
Jan 12 16:12:37 rh-khost1 systemd[1]: Detected architecture x86-64.

So dmesg _does_ show systemd messages, systemd starts a couple of lines
later, and it then reads all the kernel messages and writes them out
with the same timestamp.

I did try systemd-analyze (blame and critical-path) earlier, but they
also showed that the delay wasn't on systemd's watch.

Thanks,

Richard

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.user

csiph-web