Mysterious 12 minute pause in boot

[ktrampe]

Still the kernel log might help

Code: Select all

journalctl -k

Also appending these:

Code: Select all

rd.shell rd.debug log_buf_len=1M

to the kernel line with the removal of

Code: Select all

rhgb quiet

could bring more light to the case.

Source: How to debug Dracut problems

Nice! Thanks, I'll study the doc you sourced.

Here's a copy/paste of the some of the journalctl -k from before, during, and after the 12 minute hang. (I think)

Code: Select all

Feb 23 09:32:36 host.domain.com kernel:  xvdc: xvdc1
Feb 23 09:32:36 host.domain.com kernel: fbcon: bochsdrmfb (fb0) is primary device
Feb 23 09:32:36 host.domain.com kernel: Console: switching to colour frame buffer device 128x48
Feb 23 09:32:36 host.domain.com kernel: Setting capacity to 33554432
Feb 23 09:32:36 host.domain.com kernel: xvda: detected capacity change from 0 to 17179869184
Feb 23 09:32:36 host.domain.com kernel: bochs-drm 0000:00:02.0: fb0: bochsdrmfb frame buffer device
Feb 23 09:32:36 host.domain.com kernel: bochs-drm 0000:00:02.0: registered panic notifier
Feb 23 09:32:36 host.domain.com kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:02.0 on minor 0
Feb 23 09:32:36 host.domain.com kernel: Setting capacity to 8388608
Feb 23 09:32:36 host.domain.com kernel: xvde: detected capacity change from 0 to 4294967296
Feb 23 09:32:37 host.domain.com kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001
Feb 23 09:32:37 host.domain.com kernel: usb 1-2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Feb 23 09:32:37 host.domain.com kernel: usb 1-2: Product: QEMU USB Tablet
Feb 23 09:32:37 host.domain.com kernel: usb 1-2: Manufacturer: QEMU 0.10.2
Feb 23 09:32:37 host.domain.com kernel: usb 1-2: SerialNumber: 1
Feb 23 09:32:37 host.domain.com kernel: input: QEMU 0.10.2 QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-2/1-2:1.0/input/input3
Feb 23 09:32:37 host.domain.com kernel: hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Pointer [QEMU 0.10.2 QEMU USB Tablet] on usb-0000:00:01.2-2/input0
Feb 23 09:32:37 host.domain.com kernel: input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4
Feb 23 09:32:37 host.domain.com kernel: tsc: Refined TSC clocksource calibration: 2659.997 MHz
Feb 23 09:32:38 host.domain.com kernel: SGI XFS with ACLs, security attributes, large block/inode numbers, no debug enabled
Feb 23 09:32:38 host.domain.com kernel: XFS (dm-1): Mounting V4 Filesystem
Feb 23 09:32:38 host.domain.com kernel: XFS (dm-1): Ending clean mount
Feb 23 09:44:41 host.domain.com systemd-journald[178]: Received SIGTERM
Feb 23 09:44:41 host.domain.com kernel: SELinux:  Disabled at runtime.
Feb 23 09:44:41 host.domain.com kernel: SELinux:  Unregistering netfilter hooks
Feb 23 09:44:41 host.domain.com kernel: type=1404 audit(1519399959.847:2): selinux=0 auid=4294967295 ses=4294967295
Feb 23 09:44:41 host.domain.com systemd-udevd[584]: starting version 208
Feb 23 09:44:42 host.domain.com kernel: input: PC Speaker as /devices/platform/pcspkr/input/input5
Feb 23 09:44:42 host.domain.com kernel: piix4_smbus 0000:00:01.3: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
Feb 23 09:44:42 host.domain.com kernel: parport_pc 00:0a: reported by Plug and Play ACPI
Feb 23 09:44:42 host.domain.com kernel: parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
Feb 23 09:44:42 host.domain.com kernel: alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
Feb 23 09:44:42 host.domain.com kernel: ppdev: user-space parallel port driver

[ktrampe]

Could the machine in question be trying to mount a local partition that no longer exists? I've had some long boot delays when a local share has suddenly disappeared, usually due to my own missteps. More like a 5 minute delay for me, never 12 minutes.

This could be possible. I quadruple-checked my /etc/fstab and /etc/crypttab, but they didn't reveal any mystery partitions. Are there other places I should check?

[ktrampe]

I suspect it's something related to kernel parameters passed.
Can we have the

Code: Select all

cat /proc/cmdline

???

Absolutely:

Code: Select all

cat /proc/cmdline
BOOT_IMAGE=/vmlinuz-3.10.0-229.11.1.el7.x86_64 root=/dev/mapper/centos--test-root ro crashkernel=auto rd.lvm.lv=centos-test/swap rd.lvm.lv=centos-test/root LANG=en_US.UTF-8

[glennzo]

Could the machine in question be trying to mount a local partition that no longer exists? I've had some long boot delays when a local share has suddenly disappeared, usually due to my own missteps. More like a 5 minute delay for me, never 12 minutes.

This could be possible. I quadruple-checked my /etc/fstab and /etc/crypttab, but they didn't reveal any mystery partitions. Are there other places I should check?

Not really. It would be real obvious (with text boot). You would see it as it was happening.

Why do we see rescue.target or rescue anything here?

Code: Select all

rescue.target @12min 10.403s
`-rescue.service @12min 10.402s
  `-sysinit.target @12min 10.389s
    `-systemd-update-utmp.service @12min 10.337s +51ms
      `-systemd-tmpfiles-setup.service @12min 10.272s +62ms
        `-rhel-import-state.service @12min 10.145s +125ms
          `-local-fs.target @12min 10.137s
            `-boot.mount @12min 7.983s +2.153s
              `-local-fs-pre.target @12min 7.979s
                `-lvm2-monitor.service @12min 2.599s +5.378s
                  `-lvm2-lvmetad.service @12min 2.911s

This was shown back in post #1. Why does this even show up? Can it be disabled?

[ktrampe]

Why do we see rescue.target or rescue anything here?

Code: Select all

rescue.target @12min 10.403s
`-rescue.service @12min 10.402s
  `-sysinit.target @12min 10.389s
    `-systemd-update-utmp.service @12min 10.337s +51ms
      `-systemd-tmpfiles-setup.service @12min 10.272s +62ms
        `-rhel-import-state.service @12min 10.145s +125ms
          `-local-fs.target @12min 10.137s
            `-boot.mount @12min 7.983s +2.153s
              `-local-fs-pre.target @12min 7.979s
                `-lvm2-monitor.service @12min 2.599s +5.378s
                  `-lvm2-lvmetad.service @12min 2.911s

This was shown back in post #1. Why does this even show up? Can it be disabled?

That was a result of a:

Code: Select all

systemd-analyze critical-chain

I'm using the rescue.target as my default target to allow me to manually mount some encrypted volumes before proceeding to multi-user.target. The 12 minute pause comes before reaching the rescue.target.

[hunter86_bg]

Does this happen with multi-user.target ?

[ktrampe]

Does this happen with multi-user.target ?

I think I understand what you're asking, but let me describe what happens in detail to be sure we're both on the same page.

Times are approximate here in MM:SS

00:00 - VM powered on
00:09 - Welcome to...
12:11 - Boot un-pauses and text flies by
12:30 - Reaches rescue.target
12:31 - User provides root PW at console
12:35 - User manually mounts encrypted volumes
12:50 - User manually proceeds to multi-user.target
13:05 - System fully operational (reaches multi-user.target)

I hope I answered your question. Please let me know if I misunderstood.

[TrevorH]

Use pastebin.centos.org to show the log when you boot with rd.debug added to the kernel command line. Once it's booted you can see the output in journalctl -ab

[ktrampe]

Use pastebin.centos.org to show the log when you boot with rd.debug added to the kernel command line. Once it's booted you can see the output in journalctl -ab

Sorry for the delay, doing this right now...

[glennzo]

Could the machine in question be trying to mount a local partition that no longer exists? I've had some long boot delays when a local share has suddenly disappeared, usually due to my own missteps. More like a 5 minute delay for me, never 12 minutes.

This could be possible. I quadruple-checked my /etc/fstab and /etc/crypttab, but they didn't reveal any mystery partitions. Are there other places I should check?

Have you compared the UUID in those files to the actual UUID's.