[2.6.27] pausing during boot (several issues)

I can confirm that this bug is still there.

While booting, in the first few seconds (between 0 and 1, according to dmesg) the message of
ACPI: EC: non-query interrupt received, switching to interrupt mode
is shown. The system appears to hang shortly after and does not respond. When pressing and releasing the power button (like when you turn on a pc) the system continues to boot properly.

I've noticed that the sound gets screwed sometimes and i don't remember where, but i've read something about the sound volume wheel being related to this.

My box is a laptop, and I can get past it by flipping AC/battery (either direction).

Is 2.6.24-19 good without acpi=debug as well or is that needed to get along without the hang.

Stefan Bader wrote:
> Is 2.6.24-19 good without acpi=debug as well or is that needed to get
> along without the hang.
>

2.6.24-19 does not need acpi=debug.

title Ubuntu 8.04.1, kernel 2.6.24-19-generic
root (hd0,4)
kernel /boot/vmlinuz-2.6.24-19-generic
root=UUID=6c1d1f33-b7c8-4c7c-9170-ad39bf061cef ro
initrd /boot/initrd.img-2.6.24-19-generic
quiet

Carl K

This sound like tied to the changes to the ec code which enable some callbacks sooner on boot. Which would make the same behaviour appear with the latest -21 kernels from proposed.
The DSDT of you had two errors but they where somewhere in the thermal zone and I am not sure this gets into play that early. I attached a changed version anyway. Loading a custom DSDT should be fixed for Intrepid. So you just can give it a try.
From the messages it seems the hang is between bus_init and ec_add which is large enough to be unhelpful. I'd have to add more debugging. I would try to get something together for a 2.6.26-5 kernel. But it may take a bit.

how do I use DSDT?

I treid http://gaugusch.at/kernel.shtml

root@dv67:/boot# ./initrd-add-dsdt initrd.img-2.6.26-5-generic DSDT.aml
+ '[' 2 -ne 2 ']'
++ mktemp -d
+ tempcpio=/tmp/tmp.CxUPQ10771
+ trap 'rm -rf $tempcpio' 0 1 2 3 15
+ gunzip -c initrd.img-2.6.26-5-generic
+ cp -f DSDT.aml /tmp/tmp.CxUPQ10771/DSDT.aml
+ cd /tmp/tmp.CxUPQ10771
+ echo DSDT.aml
+ cpio -H newc -o -A -O /tmp/tmp.CxUPQ10771/initramfs.cpio
69 blocks
+ cd /boot
+ gzip -c /tmp/tmp.CxUPQ10771/initramfs.cpio
+ rm -rf /tmp/tmp.CxUPQ10771

root@dv67:/boot# reboot

paused at
[ 0.560301] ACPI: EC: non-query interrupt received, switching to interrupt mo
hit power to continue.

carl@dv67:~$ dmesg | grep "Looking for DSDT in initramfs"
(nothing)

curious: is this going to have any effect before:
[ 0.684193] checking if image is initramfs... it is

cuz the pause comes before that happens.

This should work by putting DSDT.aml into /etc/initramfs-tools and then running
update-initramfs -u -k $(uname -r)

That would happen very much to the beginning

[ 30.747160] Early unpacking initramfs... done
[ 31.050966] ACPI: Core revision 20070126
[ 31.051091] ACPI: Looking for DSDT in initramfs... error, file /DSDT.aml not found.
...
[ 31.613453] ACPI: EC: Look up EC in DSDT
[ 31.615099] ACPI: BIOS _OSI(Linux) query ignored via DMI
[ 31.615702] ACPI: Interpreter enabled

[ 0.000000] ACPI: DSDT 7BF5C167, 87DF (r1 NVIDIA MCP67 6040000 MSFT 3000000)

[ 0.448028] ACPI: Core revision 20080321
[ 0.450665] ACPI: Looking for DSDT in initramfs... successfully read 34783 bytes from /DSDT.aml.
[ 0.450826] ACPI: Override [DSDT- MCP67], this is unsafe: tainting kernel
[ 0.450893] ACPI: Table DSDT replaced by host OS
[ 0.451042] ACPI: DSDT 00000000, 87DF (r1 NVIDIA MCP67 6040000 MSFT 3000000)
[ 0.451205] ACPI: DSDT override uses original SSDTs unless "acpi_no_auto_ssdt"
[ 0.456028] ENABLING IO-APIC IRQs

[ 0.584031] Setting up standard PCI resources
[ 0.584683] ACPI: EC: Look up EC in DSDT
[ 0.586820] ACPI: BIOS _OSI(Linux) query ignored via DMI
[ 0.587522] ACPI: Interpreter enabled
[ 0.587583] ACPI: (supports S0 S3 S4 S5)
[ 0.587828] ACPI: Using IOAPIC for interrupt routing
[ 0.588053] ACPI: EC: non-query interrupt received, switching to interrupt mode

pause till I hit power

I don't quite understand the wording of "DSDT override uses original SSDTs unless "acpi_no_auto_ssdt" so I tried it:

[ 0.450665] ACPI: Looking for DSDT in initramfs... successfully read 34783 bytes from /DSDT.aml.
[ 0.450826] ACPI: Override [DSDT- MCP67], this is unsafe: tainting kernel
[ 0.450893] ACPI: Table DSDT replaced by host OS
[ 0.451042] ACPI: DSDT 00000000, 87DF (r1 NVIDIA MCP67 6040000 MSFT 3000000)
[ 0.452028] ACPI: SSDT ignored due to "acpi_no_auto_ssdt"

and still waits at
[ 0.588165] ACPI: EC: non-query interrupt received, switching to interrupt mode

Ok, doesn't change anything. I will prepare a debug kernel based in 2.6.26-5 and post you a link when I am done.

Ok, I uploaded a first version for debugging. It lies at
http://people.ubuntu.com/~smb/bug254668

Can you install this and post the output. Thanks

no help.

[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 2.6.26-5-generic (root@eddie) (gcc version 4.3.1 (Ubuntu 4.3.1-8ubuntu1) ) #1 SMP Wed Aug 27 19:44:26 UTC 2008 (Ubuntu 2.6.26-5.13ecdbg-generic)
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: 0000000000000000 - 000000000009e000 (usable)
[ 0.000000] BIOS-e820: 000000000009e000 - 00000000000a0000 (reserved)
[ 0.000000] BIOS-e820: 00000000000d2000 - 0000000000100000 (reserved)
[ 0.000000] BIOS-e820: 0000000000100000 - 000000007bf50000 (usable)
[ 0.000000] BIOS-e820: 000000007bf50000 - 000000007bf65000 (ACPI data)
[ 0.000000] BIOS-e820: 000000007bf65000 - 000000007bf66000 (ACPI NVS)
[ 0.000000] BIOS-e820: 000000007bf66000 - 0000000080000000 (reserved)
[ 0.000000] BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
[ 0.000000] BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
[ 0.000000] BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
[ 0.000000] BIOS-e820: 00000000fff80000 - 0000000100000000 (reserved)
[ 0.000000] 1087MB HIGHMEM available.
[ 0.000000] 896MB LOWMEM available.
[ 0.000000] found SMP MP-table at [c00f8220] 000f8220
[ 0.000000] Entering add_active_range(0, 0, 507728) 0 entries of 256 used
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0 -> 4096
[ 0.000000] Normal 4096 -> 229376
[ 0.000000] HighMem 229376 -> 507728
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[1] active PFN ranges
[ 0.000000] 0: 0 -> 507728
[ 0.000000] On node 0 totalpages: 507728
[ 0.000000] DMA zone: 36 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 4060 pages, LIFO batch:0
[ 0.000000] Normal zone: 1980 pages used for memmap
[ 0.000000] Normal zone: 223300 pages, LIFO batch:31
[ 0.000000] HighMem zone: 2447 pages used for memmap
[ 0.000000] HighMem zone: 275905 pages, LIFO batch:31
[ 0.000000] Movable zone: 0 pages used for memmap
[ 0.000000] DMI present.
[ 0.000000] ACPI: RSDP 000F8250, 0024 (r2 PTLTD )
[ 0.000000] ACPI: XSDT 7BF5C0FB, 006C (r1 HPQOEM SLIC-MPC 6040000 LTP 0)
[ 0.000000] ACPI: FACP 7BF649BA, 00F4 (r3 NVIDIA MCP67-M 6040000 PTL_ F4240)
[ 0.000000] ACPI: DSDT 7BF5C167, 87DF (r1 NVIDIA MCP67 6040000 MSFT 3000000)
[ 0.000000] ACPI: FACS 7BF65FC0, 0040
[ 0.000000] ACPI: TCPA 7BF64AAE, 0032 (r1 Phoeni x 6040000 TL 0)
[ 0.000000] ACPI: SRAT 7BF64AE0, 00A0 (r1 AMD HAMMER 6040000 AMD 1)
[ 0.000000] ACPI: SSDT 7BF64B80, 0206 (r1 PTLTD POWERNOW 6040000 LTP 1)
[ 0.000000] ACPI: MCFG 7BF64D86, 003C (r1 PTLTD MCFG 6040000 LTP 0)
[ 0.000000] ACPI: HPET 7BF64DC2, 0038 (r1 PTLTD HPETTBL 6040000 LTP 1)
[ 0.000000] ACPI: APIC 7BF64DFA, 0068 (r1 PTLTD APIC 6040000 LTP 0)
[ 0.000000] ACPI: BOOT 7BF64E62, 0028 (r1 PTLTD $SBFTBL$ 6040000 LTP 1)
[ 0.000000] ACPI: SLIC 7BF64E8A, 0176 (r1 HPQOEM SLIC-MPC 6040000 LTP ...

The Ubuntu Kernel Team is planning to move to the 2.6.27 kernel for the upcoming Intrepid Ibex 8.10 release. As a result, the kernel team would appreciate it if you could please test this newer 2.6.27 Ubuntu kernel. There are one of two ways you should be able to test:

1) If you are comfortable installing packages on your own, the linux-image-2.6.27-* package is currently available for you to install and test.

--or--

2) The upcoming Alpha5 for Intrepid Ibex 8.10 will contain this newer 2.6.27 Ubuntu kernel. Alpha5 is set to be released Thursday Sept 4. Please watch http://www.ubuntu.com/testing for Alpha5 to be announced. You should then be able to test via a LiveCD.

Please let us know immediately if this newer 2.6.27 kernel resolves the bug reported here or if the issue remains. More importantly, please open a new bug report for each new bug/regression introduced by the 2.6.27 kernel and tag the bug report with 'linux-2.6.27'. Also, please specifically note if the issue does or does not appear in the 2.6.26 kernel. Thanks again, we really appreicate your help and feedback.

http://people.ubuntu.com/~smb/bug254668/linux-image-2.6.26-5-generic_2.6.26-5.13ecdbg2_i386.deb

looks like debug output overflowed the dmesg buffer, so I took a picture when it stopped, and quicly after i started it, but I missed some.

Now I need it to pause every few lines like the .27 kernel was doing.

Got the next iteration of the debug kernel up. Please try and post the results.

(01:05:29 PM) smb: CarlFK, I put up another debug kernel for you to my peoples page, I you could give that a try and add the output to the report...

http://people.ubuntu.com/~smb/bug254668/linux-image-2.6.26-5-generic_2.6.26-5.13ecdbg3_i386.deb

around the hang - btw I waited a good 10 seconds, but the timestamp doesn't show it, so it's like the clock paused?

[ 0.604031] ACPI: acpi_bus_scan()
[ 0.604031] ACPI: Adding CPU0
[ 0.604031] PM: Adding info for acpi:ACPI0007:00
[ 0.604031] ACPI: Adding CPU1
[ 0.604031] PM: Adding info for acpi:ACPI0007:01
[ 0.604031] ACPI: Adding _SB
[ 0.604031] PM: Adding info for acpi:device:00
[ 0.604031] ACPI: Adding SLPB
[ 0.604031] PM: Adding info for acpi:PNP0C0E:00
[ 0.604031] ACPI: Adding ACAD
[ 0.604031] PM: Adding info for acpi:ACPI0003:00
[ 0.604031] ACPI: Adding BAT0
[ 0.606598] ACPI: EC: non-query interrupt received, switching to interrupt mode

pause

[ 0.606676] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.616031] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.617599] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.619810] PM: Adding info for acpi:PNP0C0A:00
[ 0.619876] ACPI: Adding LID
[ 0.619957] PM: Adding info for acpi:PNP0C0D:00
[ 0.619995] ACPI: Adding QLBD

Somehow there is something related to the BAT0 device. The things that are clear:
BAT0 has a _STA (dynamic status) method which gets called when adding the object. This status method accesses one bit in the embedded controller which will (that is my assumption since the address space handler for the EC has been installed) call the space handler.

That would first enable burst mode, read from the embedded controller address and then disables the burst mode. Enabling the burst mode should generate the first GPE interrupt that turns on GPE mode.
Here is the first part I don't understand. Between the two messages the pause is supposed to be is one function call that does nothing. It would make a little bit more sense if the pause would be one message later.

Also, with or without GPE mode, whole code uses either msleep and compares jiffie values or uses wait_event_timeout which also should abort after some time. Which does not happen. That again would somehow make a bit of sense with your observation that the timestamps did not seem to be advanced after the pause. In that case maybe the first msleep while still in polling mode is stuck and things advance after pressing the power button or toggling AC because that causes an interruption which advances the timers again. I will try to prepare a kernel that looks ahead that road. Maybe in the meantime, what happens when playing with hpet=disable or highres=off?

[ 0.687366] ACPI: PCI Interrupt Link [LPMU] (IRQs *11)
[ 0.688855] Linux Plug and Play Support v0.97 (c) Adam Belay
[ 0.688855] pnp: PnP ACPI init
[ 0.688855] PM: Adding info for No Bus:pnp0
[ 0.688855] ACPI: bus type pnp registered
[ 0.689888] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.689888] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.689888] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.690797] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.690807] PM: Adding info for pnp:00:00
[ 0.691919] PM: Adding info for pnp:00:01
[ 0.692602] PM: Adding info for pnp:00:02
[ 0.693528] PM: Adding info for pnp:00:03
[ 0.693888] PM: Adding info for pnp:00:04
[ 0.693888] PM: Adding info for pnp:00:05
[ 0.693888] PM: Adding info for pnp:00:06
[ 0.693888] PM: Adding info for pnp:00:07
[ 0.693888] PM: Adding info for pnp:00:08
[ 0.693888] PM: Adding info for pnp:00:09
[ 0.693888] PM: Adding info for pnp:00:0a
[ 0.693888] PM: Adding info for pnp:00:0b
[ 0.693888] pnp: PnP ACPI: found 12 devices
[ 0.693888] ACPI: ACPI bus type pnp unregistered
[ 0.693888] PnPBIOS: Disabled by ACPI PNP
[ 0.693898] PCI: Using ACPI for IRQ routing

pause

[ 0.703099] NET: Registered protocol family 8
[ 0.703160] NET: Registered protocol family 20
[ 0.703977] NetLabel: Initializing
[ 0.704036] NetLabel: domain hash size = 128
[ 0.704095] NetLabel: protocols = UNLABELED CIPSOv4
[ 0.704167] NetLabel: unlabeled traffic allowed by default
[ 0.704234] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 31
[ 0.704473] hpet0: 3 32-bit timers, 25000000 Hz
[ 0.705579] AppArmor: AppArmor Filesystem Enabled
[ 0.705643] ACPI: acpi_rtc_init()
[ 0.705722] ACPI: RTC can wake from S4
[ 0.707129] Switched to high resolution mode on CPU 0
[ 0.707176] system 00:02: iomem range 0xe0000000-0xefffffff could not be reserved
[ 0.707176] system 00:03: ioport range 0x1000-0x107f has been reserved
[ 0.707176] system 00:03: ioport range 0x1080-0x10ff has been reserved
[ 0.707176] system 00:03: ioport range 0x1400-0x147f has been reserved
[ 0.707176] system 00:03: ioport range 0x1480-0x14ff has been reserved

looks like more is going to dmesg than the screen. guessing the extra debugging?

[ 0.695225] ACPI: bus type pnp registered
[ 0.695225] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.695225] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.695324] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.695324] ACPI: EC: acpi_ec_gpe_handler() returns handled
[ 0.695690] PM: Adding info for pnp:00:00
[ 0.696969] PM: Adding info for pnp:00:01
[ 0.697816] PM: Adding info for pnp:00:02
[ 0.698907] PM: Adding info for pnp:00:03
[ 0.699225] PM: Adding info for pnp:00:04
[ 0.699225] PM: Adding info for pnp:00:05
[ 0.699225] PM: Adding info for pnp:00:06
[ 0.699225] PM: Adding info for pnp:00:07
[ 0.699225] PM: Adding info for pnp:00:08
[ 0.699225] PM: Adding info for pnp:00:09
[ 0.699225] PM: Adding info for pnp:00:0a
[ 0.699225] PM: Adding info for pnp:00:0b
[ 0.699516] pnp: PnP ACPI: found 12 devices
[ 0.699516] ACPI: ACPI bus type pnp unregistered
[ 0.699516] PnPBIOS: Disabled by ACPI PNP
[ 0.699516] PCI: Using ACPI for IRQ routing

pause

[ 0.710132] NET: Registered protocol family 8
[ 0.710192] NET: Registered protocol family 20
[ 0.711012] NetLabel: Initializing
[ 0.711071] NetLabel: domain hash size = 128
[ 0.711131] NetLabel: protocols = UNLABELED CIPSOv4
[ 0.711202] NetLabel: unlabeled traffic allowed by default
[ 0.711225] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 31
[ 0.711225] hpet0: 3 32-bit timers, 25000000 Hz
[ 0.711225] AppArmor: AppArmor Filesystem Enabled
[ 0.711225] ACPI: acpi_rtc_init()
[ 0.711225] ACPI: RTC can wake from S4
[ 0.713426] Switched to high resolution mode on CPU 0
[ 0.713425] Switched to high resolution mode on CPU 1
[ 0.713442] system 00:02: iomem range 0xe0000000-0xefffffff could not be reserved
[ 0.713520] system 00:03: ioport range 0x1000-0x107f has been reserved
[ 0.713584] system 00:03: ioport range 0x1080-0x10ff has been reserved
[ 0.713653] system 00:03: ioport range 0x1400-0x147f has been reserved
[ 0.713717] system 00:03: ioport range 0x1480-0x14ff has been reserved
[ 0.713780] system 00:03: ioport range 0x1800-0x187f has been reserved
[ 0.713843] system 00:03: ioport range 0x1880-0x18ff has been reserved
[ 0.713912] system 00:04: ioport range 0x360-0x361 has been reserved
:

I have an AMD Turion 64 X2 running the Intrepid/x86_64 (HP Pavilion dv2000).
I didn't have any problem with 2.6.26-5, but with 2.6.27(-1 and -2) the kernel stops booting after "ACPI: RTC can wake from S4". The system will boot with acpi=off, but that prevents the non-free nvidia driver from working properly.

Actually, 2.6.27-2 (perhaps -1) as well, did boot, but it took about 9 minutes (in Single User mode) before I could get to the "drop to root sell prompt". There was a very long delay where I previously believed it was frozen ("ACPI: RTC can wake from S4"). It also took a long delay after "sda:" (when the partitions are detected, I believe). And then there was another long delay after "Setting kernel variables: wine"

The dmesg log shows this at a few points:
BUG: soft lockup - CPU#0 stuck for 155s! [swapper:0]
BUG: soft lockup - CPU#1 stuck for 155s! [modprobe:2174]
BUG: soft lockup - CPU#0 stuck for 144s! [swapper:0]
BUG: soft lockup - CPU#0 stuck for 144s! [uname:4136]

I'm continuing the boot - I should be able to attach the full dmesg log later (already seeing more of these 2 minute delays, so it may take a while)

Marques Johansson wrote:
> Actually, 2.6.27-2 (perhaps -1) as well, did boot, but it took about 9
> minutes (in Single User mode) before I could get to the "drop to root
> sell prompt". There was a very long delay where I previously believed
> it was frozen ("ACPI: RTC can wake from S4"). It also took a long delay
> after "sda:" (when the partitions are detected, I believe). And then
> there was another long delay after "Setting kernel variables: wine"
>
> The dmesg log shows this at a few points:
> BUG: soft lockup - CPU#0 stuck for 155s! [swapper:0]
> BUG: soft lockup - CPU#1 stuck for 155s! [modprobe:2174]
> BUG: soft lockup - CPU#0 stuck for 144s! [swapper:0]
> BUG: soft lockup - CPU#0 stuck for 144s! [uname:4136]
>

I think you want to post to:

.27 CPU#1 stuck for 113s! [events/1:10]
https://bugs.launchpad.net/bugs/262437

I am having just enough troubles with both kernels it is hard to tell what is a
different bug.

Carl K

Since there is still this strange stop of advancing the timestamps: I found some hint on another thread which mentioned to use noacpitimer as a boot option. Could one of you try whether this one changes one of the problems?

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 noacpitimer

no help

(08:45:36 AM) mjg59: CarlFK: You mean noapictimer, right?

no help.

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 noapictimer

[ 0.700336] PM: Adding info for pnp:00:0b
[ 0.700336] pnp: PnP ACPI: found 12 devices
[ 0.700336] ACPI: ACPI bus type pnp unregistered
[ 0.700398] PnPBIOS: Disabled by ACPI PNP
[ 0.700398] PCI: Using ACPI for IRQ routing

pause

[ 0.711939] NET: Registered protocol family 8
[ 0.711999] NET: Registered protocol family 20

(09:18:35 AM) smb_tp: CarlFK, I did not look to deeply yet. But I remember there have been several hangs. Can you try noapictimer without too much effort on a 2.6.27?

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 noapictimer

doesn't pause at "PCI: Using ACPI for IRQ routing" but does pause at some other places.

To continue, don't have to hit the power button - keyboard events, like tapping the shift key, will un pause it. If I hold down the shift key for the whole boot process, it doesn't seem to pause (guessing keyboard repeat?)

(10:18:12 AM) CarlFK: smb_tp: so I was trying to note all the places .27 pauses, and i ran out of battery
(10:18:56 AM) CarlFK: plugged in, booted, and it seems like it is still pausing, but continuing on its own without me hitting any keys
(10:19:17 AM) CarlFK: as the battery charges, does that generate some sort of event, similar to hitting the power button?
(10:22:10 AM) smb_tp: CarlFK, I can't say for sure. I won't think so on charge.

below is the dmesg from booting with power, then without. when it paused, I gave it about 5 seconds, then tapped the shift key.

Used this .py to look for the gaps:

dmesgs = open('/mnt/nfs/cw1b/carl/a/dmesg9.txt').read().split('\n')
# make a list of (tiems as floats, original line (with ts))
l=[]
for i in dmesgs:
    if i: # skip blank lines (like at the end)
        ts=i[1:13]
        # print ts, i
        l.append( (float(ts), i) )
# look for gaps
for i in xrange(len(l)-1):
    d = l[i+1][0] - l[i][0]
    if d>1:
        for x in l[i-3:i+1]: print x[1]
        print "(pause)"
        for x in l[i+1:i+3]: print x[1]
        print

gaps in boot while on AC power (on a drained battery, so it was charging too):

[ 3.030625] libata version 3.00 loaded.
[ 3.059201] usb usb1: configuration #1 chosen from 1 choice
[ 3.059298] hub 1-0:1.0: USB hub found
[ 3.059370] hub 1-0:1.0: 7 ports detected
(pause)
[ 58.727075] Clocksource tsc unstable (delta = 4398044420614 ns)
[ 58.728022] ACPI: PCI Interrupt Link [Z018] enabled at IRQ 18

[ 58.728354] ohci_hcd 0000:00:04.0: irq 18, io mem 0xf6487000
[ 58.834595] usb usb2: configuration #1 chosen from 1 choice
[ 58.834689] hub 2-0:1.0: USB hub found
[ 58.834756] hub 2-0:1.0: 2 ports detected
(pause)
[ 147.069064] ACPI: PCI Interrupt Link [LUS2] enabled at IRQ 22
[ 147.069137] ehci_hcd 0000:00:02.1: PCI INT B -> Link[LUS2] -> GSI 22 (level, low) -> IRQ 22

[ 147.069317] ehci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 3
[ 147.069418] ehci_hcd 0000:00:02.1: debug port 1
[ 147.069486] ehci_hcd 0000:00:02.1: cache line size of 64 is not supported
[ 147.069501] ehci_hcd 0000:00:02.1: irq 22, io mem 0xf6489000
(pause)
[ 161.672469] usb 2-1: new full speed USB device using ohci_hcd and address 2
[ 174.346769] ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004

[ 147.069418] ehci_hcd 0000:00:02.1: debug port 1
[ 147.069486] ehci_hcd 0000:00:02.1: cache line size of 64 is not supported
[ 147.069501] ehci_hcd 0000:00:02.1: irq 22, io mem 0xf6489000
[ 161.672469] usb 2-1: new full speed USB device using ohci_hcd and address 2
(p...

gaps in boot while on battery:

[ 3.092828] ohci_hcd 0000:00:04.0: setting latency timer to 64
[ 3.092831] ohci_hcd 0000:00:04.0: OHCI Host Controller
[ 3.092916] ohci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 2
[ 3.093002] ohci_hcd 0000:00:04.0: irq 18, io mem 0xf6487000
(pause)
[ 13.611857] Clocksource tsc unstable (delta = 4398045405880 ns)
[ 13.614080] usb usb2: configuration #1 chosen from 1 choice

[ 13.611857] Clocksource tsc unstable (delta = 4398045405880 ns)
[ 13.614080] usb usb2: configuration #1 chosen from 1 choice
[ 13.614176] hub 2-0:1.0: USB hub found
[ 13.614245] hub 2-0:1.0: 2 ports detected
(pause)
[ 66.849293] ACPI: PCI Interrupt Link [LUS2] enabled at IRQ 22
[ 66.849367] ehci_hcd 0000:00:02.1: PCI INT B -> Link[LUS2] -> GSI 22 (level, low) -> IRQ 22

[ 66.952571] ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 66.952735] usb usb3: configuration #1 chosen from 1 choice
[ 66.952766] hub 3-0:1.0: USB hub found
[ 66.952775] hub 3-0:1.0: 7 ports detected
(pause)
[ 151.083790] ACPI: PCI Interrupt Link [Z019] enabled at IRQ 22
[ 151.083858] ehci_hcd 0000:00:04.1: PCI INT B -> Link[Z019] -> GSI 22 (level, low) -> IRQ 22

[ 151.089361] ehci_hcd 0000:00:04.1: new USB bus registered, assigned bus number 4
[ 151.089466] ehci_hcd 0000:00:04.1: debug port 1
[ 151.089529] ehci_hcd 0000:00:04.1: cache line size of 64 is not supported
[ 151.089535] ehci_hcd 0000:00:04.1: irq 22, io mem 0xf6489400
(pause)
[ 165.763727] usb 2-1: new full speed USB device using ohci_hcd and address 2
[ 165.866916] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004

[ 165.866916] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 165.867105] usb usb4: configuration #1 chosen from 1 choice
[ 165.867133] hub 4-0:1.0: USB hub found
[ 165.867140] hub 4-0:1.0: 2 ports detected
(pause)
[ 174.346784] hub 2-0:1.0: unable to enumerate USB device on port 1
[ 183.274937] pata_acpi 0000:00:06.0: setting latency timer to 64

[ 165.867105] usb usb4: configuration #1 chosen from 1 choice
[ 165.867133] hub 4-0:1.0: USB hub found
[ 165.867140] hub 4-0:1.0: 2 ports detected
[ 174.346784] hub 2-0:1.0: unable to enumerate USB device on port 1
(pause)
[ 183.274937] pata_acpi 0000:00:06.0: setting latency timer to 64
[ 183.275380] ACPI: PCI Interrupt Link [LSI0] enabled at IRQ 23

[ 183.275645] forcedeth: Reverse Engineered nForce ethernet driver. Version 0.61.
[ 183.276057] ACPI: PCI Interrupt Link [LMAC] enabled at IRQ 20
[ 183.276124] forcedeth 0000:00:0a.0: PCI INT A -> Link[LMAC] -> GSI 20 (level, low) -> IRQ 20
[ 183.276211] forcedeth 0000:00:0a.0: setting latency timer to 64
(pause)
[ 203.965474] forcedeth 0000:00:0a.0: ifname eth0, PHY OUI 0x732 @ 1, addr 00:1e:68:09:25:f6
[ 203.971700] forcedeth 0000:00:0a.0: highdma pwrctl mgmt timirq lnktim msi desc-v3

[ 204.032757] scsi0 : pata_amd
[ 204.032916] scsi1 : pata_amd
[ 204.033316] ata1: PATA max UDMA/133 cmd 0x1f0 ctl 0x3f6 bmdma 0x30c0 irq 14
[ 204.033381] ata2: PATA max UDMA/133 cmd 0x170 ctl 0x376 bmdma 0x30c8 irq 15
(pause)
[ 218.112276] ata1.00: ATAPI: TSSTcorp CDDVDW ...

Some more digging around the C1E hint. One thing is that 2.6.27 uses a special idle function where 2.6.26 still does that somewhat differently. Is this the right direction? Can C1E be disabled from the BIOS? Probably less promising since I don't know whether this gets into trouble with C1E, is to try idle=poll (not good for normal operation).

I also uploaded http://people.ubuntu.com/~smb/bug254668/linux-headers-2.6.27-3-generic_2.6.27-3.4smb1_i386.deb which contains one fix to clockevents that went to the mailing list today.

http://people.ubuntu.com/~smb/bug254668/linux-image-2.6.27-3-generic_2.6.27-3.3smb2_i386.deb

[ 3.087260] hub 2-0:1.0: USB hub found
[ 3.087330] hub 2-0:1.0: 2 ports detected
[ 3.098646] SCSI subsystem initialized
[ 3.122770] libata version 3.00 loaded.
(pause)
[ 13.701303] Clocksource tsc unstable (delta = 4398045486566 ns)
[ 13.702453] ACPI: PCI Interrupt Link [LUS2] enabled at IRQ 22

[ 13.702703] ehci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 3
[ 13.702809] ehci_hcd 0000:00:02.1: debug port 1
[ 13.702872] ehci_hcd 0000:00:02.1: cache line size of 64 is not supported
[ 13.702888] ehci_hcd 0000:00:02.1: irq 22, io mem 0xf6489000
(pause)
[ 19.272505] usb 2-1: new full speed USB device using ohci_hcd and address 2
[ 22.373778] ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004

[ 13.702809] ehci_hcd 0000:00:02.1: debug port 1
[ 13.702872] ehci_hcd 0000:00:02.1: cache line size of 64 is not supported
[ 13.702888] ehci_hcd 0000:00:02.1: irq 22, io mem 0xf6489000
[ 19.272505] usb 2-1: new full speed USB device using ohci_hcd and address 2
(pause)
[ 22.373778] ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 22.373997] usb usb3: configuration #1 chosen from 1 choice

[ 22.373778] ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 22.373997] usb usb3: configuration #1 chosen from 1 choice
[ 22.374086] hub 3-0:1.0: USB hub found
[ 22.374153] hub 3-0:1.0: 7 ports detected
(pause)
[ 26.063772] ACPI: PCI Interrupt Link [Z019] enabled at IRQ 22
[ 26.063839] ehci_hcd 0000:00:04.1: PCI INT B -> Link[Z019] -> GSI 22 (level, low) -> IRQ 22

[ 26.064012] ehci_hcd 0000:00:04.1: new USB bus registered, assigned bus number 4
[ 26.064109] ehci_hcd 0000:00:04.1: debug port 1
[ 26.064172] ehci_hcd 0000:00:04.1: cache line size of 64 is not supported
[ 26.064179] ehci_hcd 0000:00:04.1: irq 22, io mem 0xf6489400
(pause)
[ 29.146302] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 29.146493] usb usb4: configuration #1 chosen from 1 choice

[ 29.146302] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 29.146493] usb usb4: configuration #1 chosen from 1 choice
[ 29.146585] hub 4-0:1.0: USB hub found
[ 29.146650] hub 4-0:1.0: 2 ports detected
(pause)
[ 32.772346] usb 2-1: device not accepting address 2, error -62
[ 32.810132] pata_acpi 0000:00:06.0: setting latency timer to 64

[ 29.146585] hub 4-0:1.0: USB hub found
[ 29.146650] hub 4-0:1.0: 2 ports detected
[ 32.772346] usb 2-1: device not accepting address 2, error -62
[ 32.810132] pata_acpi 0000:00:06.0: setting latency timer to 64
(pause)
[ 35.679016] hub 2-0:1.0: unable to enumerate USB device on port 1
[ 32.810132] ACPI: PCI Interrupt Link [LSI0] enabled at IRQ 23

[ 32.810132] ACPI: PCI Interrupt Link [LSI0] enabled at IRQ 23
[ 32.810132] pata_acpi 0000:00:09.0: PCI INT A -> Link[LSI0] -> GSI 23 (level, low) -> IRQ 23
[ 32.810132] pata_acpi 0000:00:09.0: setting latency timer to 64
[ 32.810132] pata_acpi 0000:00:09.0: PCI INT A disabled
(pause)
[ 35.681069] forcedeth: Reverse Engineered ...

Unfortunately nothing looks out of place to me (beside of the pauses of course). I put together all the patches that were discussed on the mailing list and uploaded a kernel with that. If you could try that as well...

If this still gives pauses, maybe try "highres=off nohz=off" for boot parameters.

And maybe try ALT+Print+q and ALT+Print+w. Since hitting a key makes the boot running on, the sysrq keys should have some effect. Use those only once or twice. They generate a bit of output to dmesg.

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 nohz=off single

[ 3.225944] ehci_hcd 0000:00:04.1: new USB bus registered, assigned bus number 2
[ 3.226041] ehci_hcd 0000:00:04.1: debug port 1
[ 3.226104] ehci_hcd 0000:00:04.1: cache line size of 64 is not supported
[ 3.226111] ehci_hcd 0000:00:04.1: irq 22, io mem 0xf6489400
(pause)
[ 24.384387] Clocksource tsc unstable (delta = 4398045992829 ns)
[ 24.384532] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004

[ 24.384532] ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 24.384785] usb usb2: configuration #1 chosen from 1 choice
[ 24.384885] hub 2-0:1.0: USB hub found
[ 24.384957] hub 2-0:1.0: 2 ports detected
(pause)
[ 174.074713] BUG: soft lockup - CPU#1 stuck for 161s! [swapper:0]
[ 174.074713] Modules linked in: ohci1394(+) pata_acpi(+) forcedeth(+) ohci_hcd(+) ieee1394 libata ehci_hcd(+) scsi_mod dock usbcore thermal processor fan uvesafb cn fuse fbcon tileblit font bitblit softcursor

[ 174.074711] [<c02dc72b>] cpuidle_idle_call+0x7b/0xd0
[ 174.074711] [<c010288d>] cpu_idle+0x7d/0x130
[ 174.074711] [<c0385353>] rest_init+0x53/0x60
[ 174.074711] =======================
(pause)
[ 285.527453] ACPI: PCI Interrupt Link [LUS0] enabled at IRQ 18
[ 285.527527] ohci_hcd 0000:00:02.0: PCI INT A -> Link[LUS0] -> GSI 18 (level, low) -> IRQ 18

[ 285.728284] ohci_hcd 0000:00:04.0: setting latency timer to 64
[ 285.728287] ohci_hcd 0000:00:04.0: OHCI Host Controller
[ 285.728371] ohci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 4
[ 285.728456] ohci_hcd 0000:00:04.0: irq 18, io mem 0xf6487000
(pause)
[ 291.714150] usb 2-2: new high speed USB device using ehci_hcd and address 3
[ 291.716358] usb usb4: configuration #1 chosen from 1 choice

[ 291.714150] usb 2-2: new high speed USB device using ehci_hcd and address 3
[ 291.716358] usb usb4: configuration #1 chosen from 1 choice
[ 291.716450] hub 4-0:1.0: USB hub found
[ 291.716524] hub 4-0:1.0: 2 ports detected
(pause)
[ 298.420370] pata_acpi 0000:00:06.0: setting latency timer to 64
[ 298.420865] ACPI: PCI Interrupt Link [LSI0] enabled at IRQ 23

[ 299.023043] ata1: SATA max UDMA/133 abar m8192@0xf6484000 port 0xf6484100 irq 221
[ 299.023117] ata2: SATA max UDMA/133 abar m8192@0xf6484000 port 0xf6484180 irq 221
[ 299.023193] ata3: SATA max UDMA/133 abar m8192@0xf6484000 port 0xf6484200 irq 221
[ 299.023267] ata4: SATA max UDMA/133 abar m8192@0xf6484000 port 0xf6484280 irq 221
(pause)
[ 305.614892] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 305.615136] ieee1394: Host added: ID:BUS[0-00:1023] GUID[00241b00964cac00]

[ 305.615739] ata1.00: ATA-8: Hitachi HTS542525K9SA00, BBFOC32P, max UDMA/100
[ 305.615807] ata1.00: 488397168 sectors, multi 16: LBA48
[ 305.616840] ata1.00: configured for UDMA/100
[ 306.202005] ata2: SATA link down (SStatus 0 SControl 300)
(pause)
[ 311.101967] ata3: SATA link down (SStatus 0 SControl 300)
[ 311.805293] ata4: SATA link down (SStatus 0 SControl 300)

[ 312.220938] Driver 'sr' needs updating - please use bus_type methods
[ 312.233383] sr0: scs...

So the soft lockups just seem to be more evidence to my theory. If I just would know better all this timer and tickless stuff. What seems to happen is that your machine enters idle and probably should be awoken by a timer tick. Which somehow doesn't happen. Interrupts are enabled to anything that causes an interrupt will also awake the CPU.
Upstream had one more change (to increase the minimum timer delay if the current minimum can't be programmed) which I included and put to -3.3smb4.
Any chance you could get a timer dump (alt+print+q) during a pause, or at least cat /proc/timer_list after boot?

carl@dv67:~$ cat /proc/timer_list |xclip

Timer List Version: v0.3
HRTIMER_MAX_CLOCK_BASES: 2
now at 354351313848 nsecs

cpu: 0
 clock 0:
  .index: 0
  .resolution: 1 nsecs
  .get_time: ktime_get_real
  .offset: 1220656718200590072 nsecs
active timers:
 clock 1:
  .index: 1
  .resolution: 1 nsecs
  .get_time: ktime_get
  .offset: 0 nsecs
active timers:
 #0: <f4d73e54>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0
 # expires at 354352000000 nsecs [in 686152 nsecs]
 #1: <f4d73e54>, hrtimer_wakeup, S:01, do_nanosleep, atd/6070
 # expires at 3779664857728 nsecs [in 3425313543880 nsecs]
  .expires_next : 354352000000 nsecs
  .hres_active : 1
  .nr_events : 16864
  .nohz_mode : 2
  .idle_tick : 354328000000 nsecs
  .tick_stopped : 0
  .idle_jiffies : 13581
  .idle_calls : 32940
  .idle_sleeps : 3724
  .idle_entrytime : 354348013048 nsecs
  .idle_waketime : 354325547568 nsecs
  .idle_exittime : 354345026528 nsecs
  .idle_sleeptime : 334352201679 nsecs
  .last_jiffies : 13586
  .next_jiffies : 13590
  .idle_expires : 354360000000 nsecs
jiffies: 13587

cpu: 1
 clock 0:
  .index: 0
  .resolution: 1 nsecs
  .get_time: ktime_get_real
  .offset: 1220656718200590072 nsecs
active timers:
 clock 1:
  .index: 1
  .resolution: 1 nsecs
  .get_time: ktime_get
  .offset: 0 nsecs
active timers:
 #0: <f4d73e54>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0
 # expires at 354353000000 nsecs [in 1686152 nsecs]
 #1: <f4d73e54>, hrtick, S:01, hrtick_start_fair, bash/6855
 # expires at 354366700722 nsecs [in 15386874 nsecs]
 #2: <f4d73e54>, it_real_fn, S:01, do_setitimer, syslogd/4814
 # expires at 379234767248 nsecs [in 24883453400 nsecs]
 #3: <f4d73e54>, hrtimer_wakeup, S:01, do_nanosleep, cron/6108
 # expires at 382800506048 nsecs [in 28449192200 nsecs]
  .expires_next : 354353000000 nsecs
  .hres_active : 1
  .nr_events : 14919
  .nohz_mode : 2
  .idle_tick : 354269000000 nsecs
  .tick_stopped : 0
  .idle_jiffies : 13568
  .idle_calls : 47766
  .idle_sleeps : 20018
  .idle_entrytime : 354335492448 nsecs
  .idle_waketime : 354343885768 nsecs
  .idle_exittime : 354343922888 nsecs
  .idle_sleeptime : 321434519696 nsecs
  .last_jiffies : 13583
  .next_jiffies : 13596
  .idle_expires : 354384000000 nsecs
jiffies: 13587

Tick Device: mode: 1
Clock Event Device: hpet
 max_delta_ns: 2147483647
 min_delta_ns: 5000
 mult: 107374182
 shift: 32
 mode: 3
 next_event: 9223372036854775807 nsecs
 set_next_event: hpet_legacy_next_event
 set_mode: hpet_legacy_set_mode
 event_handler: tick_handle_oneshot_broadcast
tick_broadcast_mask: 00000003
tick_broadcast_oneshot_mask: 00000000

Tick Device: mode: 1
Clock Event Device: lapic
 max_delta_ns: 671076287
 min_delta_ns: 1199
 mult: 53688073
 shift: 32
 mode: 3
 next_event: 354352000000 nsecs
 set_next_event: lapic_next_event
 set_mode: lapic_timer_setup
 event_handler: hrtimer_interrupt

Tick Device: mode: 1
Clock Event Device: lapic
 max_delta_ns: 671076287
 min_delta_ns: 119...

I am still looking through the code to check whether there is something out of bounds. Somehow the next_event value of the hpet seems a bit high. And also the masks need some research.
Meanwhile, there have been more changes upstream to the related code. I gathered together everything that seemed to be related to the problem area and uploaded a new kernel (smb5).

One thing I forgot to ask: which clocksource does the kernel end up with? (sudo cat /sys/devices/system/clocksource/clocksource0/current_clocksource) and which are available (/sys/devices/system/clocksource/clocksource0/available_clocksource).
Also when trying the kernel, add "apic=debug and debug" to the commandline.

carl@dv67:~$ uname -a
Linux dv67 2.6.27-3-generic #1 SMP Mon Sep 8 14:08:15 UTC 2008 i686 GNU/Linux
carl@dv67:~$ sudo cat /sys/devices/system/clocksource/clocksource0/current_clocksource
hpet
carl@dv67:~$ sudo cat /sys/devices/system/clocksource/clocksource0/available_clocksource
hpet acpi_pm jiffies tsc

still pauses, SysRq alone still resumes. (puts a ^\ on the console too)

I use the option acpi=off and start good, but the power settings or management of energy dont work over my laptop.

Also I put on this boot line on grub menu.lst:
"kernel /boot/vmlinuz-2.6.27-2-generic root=UUID=88917a1d-a2f6-4e3f-8742-d770e2b58ce4 ro splash locale=es_ES noapictimer"
and work fine, I don't see any bad thing.

Can some call me wath is this option (noapictimer)

what errors or missfuntionality have with noapictimer option?
I use amd64 x2 and 2.6.27-2-generic

@vnieto,

noapictimer prevents the kernel from using the local apic timer. However this option is only used for 64bit kernels and only takes effect with multiple CPU (cores). So it is not a solution for the 32bit kernel also handled here.

You can try the smb5 test kernel from http://people.ubuntu.com/~smb/bug254668/ which should allow you to boot without the noapictimer option.

Unfortunately I had not much time the last days to make progress. Just a note to you (and also to myself not to forget): One detail I noticed is that first the clocksource should be tsc (because there is the message later about that being unstable) but actually this should be marked unstable much sooner. The code that enabled broadcast (since C1E is detected) should also mark tsc unstable because of halt in c1e. Strange this does not happen...

I use amd64 x 2 (double core) I will have any problem using niapictimer option?
If I use te smb5 test kernel don't wrk mi nvidia card.

@vnieto
Your nvidia module from the previous kernel, 2.6.27-2 (found in updates/dkms/) can be copied to the same folder in 2.6.27-3 (smb5).

Since there is now a 2.6.27-3 is now in the repository (based on rc6), you may just want to "apt-get --reinstall install linux-image-2.6.27-3-generic" .. That should run dkms for you and update the nvidia module.

I dont undestant wath i must do to this.
Please explainme better.

I install 2.6.27-3 from repository but don't work (Pausing during boot) and i need put the noapictimer optión on grub.

I don't know the different betwen smb5 and rc6, can you explain me the different and if I need install smb5 version to solve mi problem?

There should be no difference between rc6 and the kernel I supplied (at least nothing additional which is not in upstream). Are your pauses the same as for Carl, meaning the boot process stops but can be triggered with any keyboard key. And after boot everything looks ok?
Or is there no way to boot successfully without the noapictimer option? If boot hangs do alt+print+q key combinations work for you?

in my case during bootup, regardless if the power cord is connected or not i
get the pauses, i can click any button to resume, currently i have 2.6.27-2
but tried 2.6.27-3 but it didnt solve the problem

On Fri, Sep 12, 2008 at 3:37 PM, Stefan Bader <email address hidden>wrote:

> There should be no difference between rc6 and the kernel I supplied (at
> least nothing additional which is not in upstream). Are your pauses the same
> as for Carl, meaning the boot process stops but can be triggered with any
> keyboard key. And after boot everything looks ok?
> Or is there no way to boot successfully without the noapictimer option? If
> boot hangs do alt+print+q key combinations work for you?
>
> --
> [2.6.27] pausing during boot (several issues)
> https://bugs.launchpad.net/bugs/254668
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>
> Status in "linux" source package in Ubuntu: Triaged
>
> Bug description:
> carl@dv67:~$ uname -a
> Linux dv67 2.6.26-5-generic #1 SMP Sat Jul 26 21:35:46 UTC 2008 i686
> GNU/Linux
>
> [ 0.548741] ACPI: EC: Look up EC in DSDT
> [ 0.551266] ACPI: BIOS _OSI(Linux) query ignored via DMI
> [ 0.552031] ACPI: Interpreter enabled
> [ 0.552031] ACPI: (supports S0 S3 S4 S5)
> [ 0.552281] ACPI: Using IOAPIC for interrupt routing
> [ 0.556031] ACPI: EC: non-query interrupt received, switching to
> interrupt mo
> de
>
> press/release power button (thinking i need to hard reboot) and it
> continues booting:
>
> [ 0.572281] ACPI: EC: GPE = 0x10, I/O: command/status = 0x66, data =
> 0x62
> [ 0.572281] ACPI: EC: driver started in interrupt mode
> [ 0.572281] ACPI: PCI Root Bridge [PCI0] (0000:00)
> [ 0.572281] PCI: Transparent bridge - 0000:00:08.0
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P2P0._PRT]
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.XVR1._PRT]
> [ 0.572315] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.XVR2._PRT]
> [ 0.608281] ACPI: PCI Interrupt Link [LNK1] (IRQs 5) *10
> [ 0.608281] ACPI: PCI Interrupt Link [LNK2] (IRQs 7) *11
> [ 0.608281] ACPI: PCI Interrupt Link [LNK3] (IRQs 10) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LNK4] (IRQs 11) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LK1E] (IRQs 16) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LK2E] (IRQs 17) *0, disabled.
> [ 0.611173] ACPI: PCI Interrupt Link [LK3E] (IRQs 18) *0, disabled.
> [ 0.611173] ACPI: PCI Interrupt Link [LK4E] (IRQs 19) *10
> [ 0.611525] ACPI: PCI Interrupt Link [LSMB] (IRQs *10)
> [ 0.611949] ACPI: PCI Interrupt Link [LUS0] (IRQs 18) *11
> [ 0.612418] ACPI: PCI Interrupt Link [LUS2] (IRQs 22) *7
> [ 0.612891] ACPI: PCI Interrupt Link [LMAC] (IRQs 20) *11
> [ 0.613359] ACPI: PCI Interrupt Link [LAZA] (IRQs 21) *10
> [ 0.613806] ACPI: PCI Interrupt Link [LGPU] (IRQs 16) *10
> [ 0.614275] ACPI: PCI Interrupt Link [LPID] (IRQs 22) *0, disabled.
> [ 0.615164] ACPI: PCI Interrupt Link [LSI0] (IRQs 23) *11
> [ 0.615302] ACPI: PCI Interrupt Link [Z018] (IRQs 18) *5
> [ 0.6157...

For those who can boot through: can you take 2.6.27-3, boot with "apic=debug debug" and wait for around 10s on each pause (so it is visible in the log). Then post dmesg and 'cat /proc/timer_list'? I would like to get a broader base of information. Thanks.

@Stefan Bader
My boot process stops but can be triggered with any keyboard key (space key). And after boot everything looks fine.
But is very low the boot process.

I attach two files 'cat /proc/timer_list' and dmesh.
Thank a lot

something new/different: boot without AC, hits first pause, plug in AC, that unpauses, and there are no further pauses. boot, pause, hitting a key still pauses more than once.

another boot, AC plugged in, went off to get coffee, came back and saw that it 'woke up' after the first pause:

[ 3.237431] hub 2-0:1.0: 2 ports detected
[ 174.074748] Clocksource tsc unstable (delta = 4398044839120 ns)

but then paused. I unplugged AC, it unpaused, then paused, plugged in AC, it continued to boot, no pause.

I am not sure this was already tried with this kernel: since tsc is known to become/be unstable anyway. What happens when booting with "clocksource=hpet"?

seems the same

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 apic=debug debug clocksource=hpet

[ 3.222078] ohci_hcd 0000:00:04.0: irq 18, io mem 0xf6487000
(paused, let set for some time - guessing 170 seconds)
[ 174.077172] Clocksource tsc unstable (delta = 4398045676210 ns)

however, now my wifi doesn't work:

lots of this:
[ 952.346330] ath5k phy0: gain calibration timeout (2462MHz)
[ 952.346349] ath5k phy0: can't reset hardware (-11)
[ 952.346356] wlan0: Failed to config new SSID to the low-level driver

me too,
Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 clocksource=hpet
pause during boot, My atheros work

wget http://people.ubuntu.com/~smb/bug254668/linux-image-2.6.27-4-generic_2.6.27-4.5_i386.deb

[ 0.000000] Linux version 2.6.27-4-generic (root@eddie) (gcc version 4.3.1 (U
buntu 4.3.1-8ubuntu1) ) #1 SMP Mon Sep 22 20:09:37 UTC 2008 (Ubuntu 2.6.27-4.5-g
eneric)

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 apic=debug debug

[ 10.998469] Timer List Version: v0.3
[ 10.998533] HRTIMER_MAX_CLOCK_BASES: 2
[ 10.998592] now at 10998468333 nsecs
[ 10.998653]
[ 10.998719] cpu: 0
[ 10.998790] clock 0:
[ 10.998854] .index: 0
[ 10.998912] .resolution: 1 nsecs
[ 10.998969] .get_time: ktime_get_real
[ 10.999124] .offset: 1222121595457071707 nsecs
[ 10.999184] active timers:
[ 10.999193] ACPI: PCI Interrupt Link [LUS0] enabled at IRQ 18
[ 10.999199] IOAPIC[0]: Set PCI routing entry (2-18 -> 0xc1 -> IRQ 18 Mode:1 Active:1)
[ 10.999208] ohci_hcd 0000:00:02.0: PCI INT A -> Link[LUS0] -> GSI 18 (level, low) -> IRQ 18
[ 10.999225] ohci_hcd 0000:00:02.0: setting latency timer to 64
[ 10.999228] ohci_hcd 0000:00:02.0: OHCI Host Controller
[ 10.999251] ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 3
[ 10.999284] ohci_hcd 0000:00:02.0: irq 18, io mem 0xf6486000
[ 10.999708] clock 1:
[ 10.999765] .index: 1
[ 10.999822] .resolution: 1 nsecs
[ 10.999883] .get_time: ktime_get
[ 11.000043] .offset: 0 nsecs
[ 11.000101] active timers:
[ 11.000160] #0: <f7077d84>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0
[ 11.000596] # expires at 11004000000 nsecs [in 5531667 nsecs]
[ 11.000658] #1: <f7077d84>, hrtimer_wakeup, S:01, do_nanosleep, sleep/2032
[ 11.001088] # expires at 11099828173 nsecs [in 101359840 nsecs]
[ 11.001151] #2: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1897
[ 11.001569] # expires at 182992302453 nsecs [in 171993834120 nsecs]
[ 11.001632] #3: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1898
[ 11.002047] # expires at 183004524693 nsecs [in 172006056360 nsecs]
[ 11.002111] #4: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1900
[ 11.002526] # expires at 183004835733 nsecs [in 172006367400 nsecs]
[ 11.002589] #5: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1945
[ 11.003004] # expires at 183094061613 nsecs [in 172095593280 nsecs]
[ 11.003067] .expires_next : 11004000000 nsecs
[ 11.003127] .hres_active : 1
[ 11.009263] .nr_events : 644
[ 11.009322] .nohz_mode : 2
[ 11.009381] .idle_tick : 2248000000 nsecs
[ 11.009441] .tick_stopped : 0
[ 11.009499] .idle_jiffies : 4294892857
[ 11.009558] .idle_calls : 2958
[ 11.009617] .idle_sleeps : 7
[ 11.009675] .idle_entrytime : 11008022013 nsecs
[ 11.009735] .idle_waketime : 2029005413 nsecs
[ 11.009796] .idle_exittime : 2245290973 nsecs
[ 11.009858] .idle_sleeptime : 9416319092 nsecs
[ 11.009918] .last_jiffies : 4294895046
[ 11.009977] .next_jiffies : 4294895059
[ 11.010037] .idle_expires : 5000000000 nsecs
[ 11.010096] jiffies: 4294895048
[ 11.010154]
[ 11.010209] cpu: 1
[ 11.0102...

Although that looks frightening at a first glance it is quite a "normal" state. The important bits (literally) are the ones in the oneshot mask of hpet. They are all 0 which basically means hpet is not used as a broadcast device at the moment. And as long as no CPU enters an idle state where the local APICs are not running, this is just how it is supposed to be.
As soon as one or both CPUs go into long idle, the corresponding bit will be set in the mask and the hpet event timer should be set to the time when the first next event occurs.
So unfortunately nothing out of place here. No stopped tick, both APICs are about to fire soon and all other timers seem reasonable, too. The pause seems to happen after the watchdog this time, compared to the other runs where the "TSC unstable" message was printed with a longer delta.

let it time out:

[ 174.039744] Timer List Version: v0.3
[ 174.039807] HRTIMER_MAX_CLOCK_BASES: 2
[ 174.039866] now at 174039743213 nsecs
[ 174.039926]
[ 174.039981] cpu: 0
[ 174.040037] clock 0:
[ 174.040094] .index: 0
[ 174.040152] .resolution: 1 nsecs
[ 174.040220] .get_time: ktime_get_real
[ 174.040379] .offset: 1222154158465093347 nsecs
[ 174.040439] active timers:
[ 174.040511] clock 1:
[ 174.040575] .index: 1
[ 174.040633] .resolution: 1 nsecs
[ 174.040691] .get_time: ktime_get
[ 174.040841] .offset: 0 nsecs
[ 174.040899] active timers:
[ 174.040917] ACPI: PCI Interrupt Link [Z019] enabled at IRQ 22
[ 174.040923] ehci_hcd 0000:00:04.1: PCI INT B -> Link[Z019] -> GSI 22 (level, low) -> IRQ 22
[ 174.040938] ehci_hcd 0000:00:04.1: setting latency timer to 64
[ 174.040941] ehci_hcd 0000:00:04.1: EHCI Host Controller
[ 174.040965] ehci_hcd 0000:00:04.1: new USB bus registered, assigned bus number 2
[ 174.041001] ehci_hcd 0000:00:04.1: debug port 1
[ 174.041007] ehci_hcd 0000:00:04.1: cache line size of 64 is not supported
[ 174.041013] ehci_hcd 0000:00:04.1: irq 22, io mem 0xf6489400
[ 174.041478] #0: <f7077d84>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0
[ 174.041921] # expires at 174044000000 nsecs [in 4256787 nsecs]
[ 174.041985] #1: <f7077d84>, hrtick, S:01, hrtick_start_fair, udevd/2028
[ 174.042405] # expires at 174057498851 nsecs [in 17755638 nsecs]
[ 174.042467] #2: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1897
[ 174.042892] # expires at 182981498453 nsecs [in 8941755240 nsecs]
[ 174.042954] #3: <f7077d84>, it_real_fn, S:01, do_setitimer, udevd/1898
[ 174.043372] # expires at 183003094733 nsecs [in 8963351520 nsecs]
[ 174.043435] .expires_next : 174044000000 nsecs
[ 174.043495] .hres_active : 1
[ 174.043553] .nr_events : 633
[ 174.043613] .nohz_mode : 2
[ 174.043671] .idle_tick : 2036000000 nsecs
[ 174.043731] .tick_stopped : 0
[ 174.043790] .idle_jiffies : 4294892804
[ 174.043849] .idle_calls : 2444
[ 174.043908] .idle_sleeps : 7
[ 174.043966] .idle_entrytime : 174042640373 nsecs
[ 174.044034] .idle_waketime : 0 nsecs
[ 174.044093] .idle_exittime : 2033370493 nsecs
[ 174.044153] .idle_sleeptime : 172414651372 nsecs
[ 174.044214] .last_jiffies : 4294935807
[ 174.044273] .next_jiffies : 4294935809
[ 174.044333] .idle_expires : 2232000000 nsecs
[ 174.044393] jiffies: 4294935807
[ 174.044451]
[ 174.044506] cpu: 1
[ 174.044563] clock 0:
[ 174.044620] .index: 0
[ 174.050730] .resolution: 1 nsecs
[ 174.050788] .get_time: ktime_get_real
[ 174.050937] .offset: 1222154158465093347 nsecs
[ 174.050997] active timers:
[ 174.051054] clock 1:
[ 174.051111] .index: 1
[ 174.051168] .resolution: 1 nsecs
[ 174.051226] .get_time: ktime_get
[ 174.051374] .offset: 0 nsecs
[ 174.051432] active timers:
[ 174.051489] #0: <f7077d84>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0
[ 174.051919] # expires at 174053000000 nsecs [in 13256787 nsecs]
[ 174.051981] #1: <6>ehci_hcd 0000:00:04...

I got this at boot [ 2.6.27-4-generic, Ibex alpha 6] :
ACPI: EC: non-query interrupt received, switching to interrupt mode.
The boot it's ok but i have some problems with integrated webcam and some error with irq assignment.

I've attached the dmesg.

Hope this can help.

Seems as I got close to get a better debug patch together, upstream has made more C1E related fixes which should solve hangs on boot. A kernel that contains the latest changes can be found at http://people.ubuntu.com/~smb/bug254668/linux-image-2.6.27-4-generic_2.6.27-4.6smb1_i386.deb

@Antonio, this message is normal and indicates no problem. If there are problems they arise from something completely different. You should put that into a separate bug.

@Stefan, thanks, i will study the situation.
Good job!

it overflowed the dmesg buffer :/

I booted the kernel from
clonezilla live experimental 20080921-intrepid
http://www.clonezilla.org/download/sourceforge/

[ 0.000000] Linux version 2.6.27-3-generic (buildd@vernadsky) (gcc version 4.3.2 (Ubuntu 4.3.2-1ubuntu6) ) #1 SMP Wed Sep 10 16:02:00 UTC 2008 (Ubuntu 2.6.27-3.4-generic)

[ 0.000000] Kernel command line: initrd=linux/clonezilla/live/initrd1.img boot=live union=aufs hostname=intrepid ocs_live_run="ocs-live-general" ocs_live_extra_param="" ocs_live_keymap="" ocs_live_batch="no" ocs_lang="" acpi=off irqpoll noapic noapm nodma nomce nolapic nosmp ip=frommedia nolocales netboot=nfs nfsroot=192.168.1.7:/var/lib/tftpboot/linux/clonezilla/ vga=6 BOOT_IMAGE=linux/clonezilla/live/vmlinuz1

no pause.

I noticed nosmp in the clonezilla boot and tired it - no pause.

[ 0.000000] Linux version 2.6.27-4-generic (root@eddie) (gcc version 4.3.1 (Ubuntu 4.3.1-8ubuntu1) ) #1 SMP Wed Sep 24 20:00:42 UTC 2008 (Ubuntu 2.6.27-4.6smb2-generic)

[ 0.000000] Kernel command line: root=UUID=270934eb-b4c5-4f17-87e4-8ebea9d98ed3 ro vga=6 apic=debug debug nosmp

is it expected that this stuff isn't showing up ?
[ 2.439186] CPU#0: enter broadcast
[ 2.439244] clockevents_set_mode(lapic, 1)
[ 2.439304] CPU#1: exit broadcast
[ 2.439363] clockevents_set_mode(lapic, 3)
[ 2.439463] CPU#0: exit broadcast

About the clonezilla kernel: If I hadn't been too tired yesterday it would have been clear to me why there are no pauses. This command line has pretty much any no<whatever> option set.

Especially nosmp, which also disables lapic. In that case the HPET is directly responsible for triggering timer interrupts. So there is no need for the code to go through broadcast and those messages are expected to not show up.

To document my thoughts on the noisy debug run:

[ 2.924895] CPU#1: enter broadcast
[ 2.924958] clockevents_set_mode(lapic, 1)
[ 2.925018] CPU#0: enter broadcast
[ 2.925077] clockevents_set_mode(lapic, 1)
<both CPUs idle>
[ 2.925136] CPU#1: exit broadcast
[ 2.925195] clockevents_set_mode(lapic, 3)
<CPU#0 idle CPU#1 active>
[ 2.925287] CPU#0: exit broadcast
[ 2.925353] clockevents_set_mode(lapic, 3)
<both CPUs active>
[ 2.925415] CPU#1: enter broadcast
[ 2.925422] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
[ 2.925543] clockevents_set_mode(lapic, 1)
<CPU#0 active CPU#1 idle>
[ 2.925603] CPU#1: exit broadcast
[ 2.925661] clockevents_set_mode(lapic, 3)
<both CPUs active>
[ 2.925767] processor ACPI0007:00: registered as cooling_device0
[ 2.925771] CPU#1: enter broadcast
[ 2.925772] clockevents_set_mode(lapic, 1)
<CPU#0 active CPU#1 idle>
[ 2.925953] ACPI: Processor [CPU0] (supports 8 throttling states)
[ 2.926144] CPU#1: exit broadcast
[ 2.926210] clockevents_set_mode(lapic, 3)
<both CPUs active>
[ 2.926412] ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])
[ 2.926703] processor ACPI0007:01: registered as cooling_device1
[ 2.926771] ACPI: Processor [CPU1] (supports 8 throttling states)
[ 2.932389] ACPI Exception (thermal-0377): AE_OK, No or invalid critical threshold [20080609]
<snip>
[ 3.733585] ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller (OHCI) Driver
[ 3.734069] ACPI: PCI Interrupt Link [LUS0] enabled at IRQ 18
[ 3.734135] IOAPIC[0]: Set PCI routing entry (2-18 -> 0xb9 -> IRQ 18 Mode:1 Active:1)
[ 3.734215] ohci_hcd 0000:00:02.0: PCI INT A -> Link[LUS0] -> GSI 18 (level, low) -> IRQ 18
[ 3.734297] ohci_hcd 0000:00:02.0: setting latency timer to 64
[ 3.734361] ohci_hcd 0000:00:02.0: OHCI Host Controller
[ 3.734471] ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1
[ 3.734570] ohci_hcd 0000:00:02.0: irq 18, io mem 0xf6486000
[ 3.771357] libata version 3.00 loaded.
[ 3.790187] usb usb1: configuration #1 chosen from 1 choice
[ 3.790284] hub 1-0:1.0: USB hub found
[ 3.790355] hub 1-0:1.0: 7 ports detected
<Pause, both CPUs not idle>
[ 17.460971] Clocksource tsc unstable (delta = 4398045749678 ns)
[ 17.462224] ACPI: PCI Interrupt Link [Z018] enabled at IRQ 18
[ 17.462294] ohci_hcd 0000:00:04.0: PCI INT A -> Link[Z018] -> GSI 18 (level, low) -> IRQ 18
[ 17.462379] ohci_hcd 0000:00:04.0: setting latency timer to 64

So I would get it from that log that neither CPU had broadcast active at the time of the pause. The question is whether the CPUs can still be in a sort of idle state...

I attach my dmesg and timer_list.

Also, this is not necessarily related to this bug, but IMHO worth noting: after working with the system several hours (programming, mainly keyboard usage) the system _may_ suddenly stop responding to mouse clicks -- mouse movement works, keyboard works, and everything works again after restarting X. Sometimes it works all day. Sometimes I have to restart X11 very often.

This timer_list belongs to the "demsg" above %-]

I wonder if the patch-set contained in commit 8553f321e0fd might solve this?

      timers: fix build error in !oneshot case
      x86: c1e_idle: don't mark TSC unstable if CPU has invariant TSC
      x86: prevent C-states hang on AMD C1E enabled machines
      clockevents: prevent mode mismatch on cpu online
      clockevents: check broadcast device not tick device
      clockevents: prevent stale tick_next_period for onlining CPUs
      x86: prevent stale state of c1e_mask across CPU offline/online
      clockevents: prevent cpu online to interfere with nohz

new kernel, still pauses:
Linux dv67 2.6.27-5-generic #1 SMP Sun Oct 5 02:34:12 CDT 2008 i686 GNU/Linux

built this one myself with:

git clone git://kernel.ubuntu.com/ubuntu/ubuntu-intrepid.git ubuntu-intrepid
cd ubuntu-intrepid/
debchange --nmu test
debian/rules debian/control.stub
bash debian/scripts/misc/getabis 2.6.27 5.8
debuild -us -uc -i -I

so that I can try suggested patch next.

(01:56:18 PM) ivoks: if i'm not wrong, that's in -5 kernel
seems so:

carl@dv67:~/src/ubuntu-kernel/ubuntu-intrepid$ git log
...
commit 8553f321e0fd29821135ac4797b5f37bf80ae2e9
Merge: be3be89... f8e256c...
Author: Linus Torvalds <email address hidden>
Date: Tue Sep 23 14:57:36 2008 -0700

    Merge branch 'timers-fixes-for-linus' of git://git.kernel.org/pub/scm/linux/

    * 'timers-fixes-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/
      timers: fix build error in !oneshot case
      x86: c1e_idle: don't mark TSC unstable if CPU has invariant TSC
      x86: prevent C-states hang on AMD C1E enabled machines
      clockevents: prevent mode mismatch on cpu online
      clockevents: check broadcast device not tick device
      clockevents: prevent stale tick_next_period for onlining CPUs
      x86: prevent stale state of c1e_mask across CPU offline/online
      clockevents: prevent cpu online to interfere with nohz

It's been suggest that https://bugs.launchpad.net/ubuntu/+source/linux-meta/+bug/273318
is the same as this bug. My reading is no, though they are related.

273318 happens on a dual-core AMD64 laptop, it involves 13 separate hangs on boot,
12 of which respond to hitting any key, and one of which doesn't but times out after a minute or two.
273318 boots much better with "noapictimer" -- then you only get the single hang that times out.
273318 is still a problem in the Intrepid Beta 2.6.27-7 kernel of today.

Can people over here comment?

i confirm its also there on the latest interpid beta

On Sun, Oct 19, 2008 at 12:31 PM, gpk <email address hidden> wrote:

> It's been suggest that
> https://bugs.launchpad.net/ubuntu/+source/linux-meta/+bug/273318
> is the same as this bug. My reading is no, though they are related.
>
> 273318 happens on a dual-core AMD64 laptop, it involves 13 separate hangs
> on boot,
> 12 of which respond to hitting any key, and one of which doesn't but times
> out after a minute or two.
> 273318 boots much better with "noapictimer" -- then you only get the single
> hang that times out.
> 273318 is still a problem in the Intrepid Beta 2.6.27-7 kernel of today.
>
> Can people over here comment?
>
> --
> [2.6.27] pausing during boot (several issues)
> https://bugs.launchpad.net/bugs/254668
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>
> Status in The Linux Kernel: Confirmed
> Status in "linux" source package in Ubuntu: Triaged
> Status in Mandriva Linux: In Progress
>
> Bug description:
> carl@dv67:~$ uname -a
> Linux dv67 2.6.26-5-generic #1 SMP Sat Jul 26 21:35:46 UTC 2008 i686
> GNU/Linux
>
> [ 0.548741] ACPI: EC: Look up EC in DSDT
> [ 0.551266] ACPI: BIOS _OSI(Linux) query ignored via DMI
> [ 0.552031] ACPI: Interpreter enabled
> [ 0.552031] ACPI: (supports S0 S3 S4 S5)
> [ 0.552281] ACPI: Using IOAPIC for interrupt routing
> [ 0.556031] ACPI: EC: non-query interrupt received, switching to
> interrupt mo
> de
>
> press/release power button (thinking i need to hard reboot) and it
> continues booting:
>
> [ 0.572281] ACPI: EC: GPE = 0x10, I/O: command/status = 0x66, data =
> 0x62
> [ 0.572281] ACPI: EC: driver started in interrupt mode
> [ 0.572281] ACPI: PCI Root Bridge [PCI0] (0000:00)
> [ 0.572281] PCI: Transparent bridge - 0000:00:08.0
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P2P0._PRT]
> [ 0.572281] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.XVR1._PRT]
> [ 0.572315] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.XVR2._PRT]
> [ 0.608281] ACPI: PCI Interrupt Link [LNK1] (IRQs 5) *10
> [ 0.608281] ACPI: PCI Interrupt Link [LNK2] (IRQs 7) *11
> [ 0.608281] ACPI: PCI Interrupt Link [LNK3] (IRQs 10) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LNK4] (IRQs 11) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LK1E] (IRQs 16) *0, disabled.
> [ 0.608281] ACPI: PCI Interrupt Link [LK2E] (IRQs 17) *0, disabled.
> [ 0.611173] ACPI: PCI Interrupt Link [LK3E] (IRQs 18) *0, disabled.
> [ 0.611173] ACPI: PCI Interrupt Link [LK4E] (IRQs 19) *10
> [ 0.611525] ACPI: PCI Interrupt Link [LSMB] (IRQs *10)
> [ 0.611949] ACPI: PCI Interrupt Link [LUS0] (IRQs 18) *11
> [ 0.612418] ACPI: PCI Interrupt Link [LUS2] (IRQs 22) *7
> [ 0.612891] ACPI: PCI Interrupt Link [LMAC] (IRQs 20) *11
> [ 0.613359] ACPI: PCI Interrupt Link [LAZA] (IRQs 21) *10
> [ 0.613806] ACPI: PCI Interrupt Link [LGPU] (IRQs 16) *10
> [ 0.614275] ACPI: PCI Interrupt Link [LPID] (IRQs 22) *0, disabled.
> [ 0.615164] ACPI: PCI Interrupt Link [LSI0] (IRQs 23) *11
> [ ...

I can get through with "acpi=noirq" -- works for both AC power and battery.

the same as Bug 289157 which I experienced

if a keyboard being pressed, the boot process will go on

 > I can get through with "acpi=noirq" -- works for both AC power and battery.

The pauses are gone but the system boots into a busybox shell :(

I am not sure if it is the same bug or another, I also have 2 hangs with 2.6.27-7 on an AMD 64x2 - System on nvidia AM32-VM-CSM-NBP-Board (Bios 1101 as of march I guess, not sure). Tried "noapic" to no result, will try acpi=noirq there... On shutdown when it says "shutting down alsa" it also hangs hangs...

I can go through with "acpi=noirq", but with black screen when shutting down

volume up and volume down work badly when the relative button being pressed on my laptop.

while in ubuntu 8.04 it worked perfectly

attached file is /proc/acpi/dsdt

the system boots into a busybox shell with nolapic, while can go through with "acpi=noirq"

"acpi=noirq" does not speed up the boot, but on the other hand seems to solve the shutdown hang at "alsa". I was researching my md5-raid performance and stumbled upon some information that suggested checking the IRQ assignments.
Voilà, the boot hang could be related to IRQ problems (while plug&play yes/or no in the bios does not matter).
Another indicator is that on Hardy, the board would never accept usb mouse and/or keyboard (for example, also very problematic with gparted-live-disks), and with intrepid now I can't even access my usb-stick. PS/2 mouse lights fine, USB mouse never does.
And yet another indicator for severe, maybe related bugs in the kernel: I always get the message (at .0 bootsecs) that I do not have MMIO (memory mapped I/O) enabled. MMIO is a technique that alows external hardware to be "mapped" into RAM and be accessible as such,ancient as from old days of RS232 etc. what do I care if I have 64M more or less with 4-6 gig?) Legacy Parallel and serial is disabled, however, legacy "HID" for USB mouse/keyboard is on.

On Hardy, USB mouse and keyboard where OK to enter the bios but after "Kernel starting up" never worked.

Unfortunatly, this Asus M2NPB-Board (NVIDIA Business Platform haha) has no option similar to the old-familar "DRAM Type for OS >64M / OS/2 select" or whatever that used to be to set the MMIO region. I have the hang shortly after mdadm starts the raid5 (which is 1xide hitachi deskstar 400gib, 1xsata wdc 500gib, 1xsata samsung 500gib... kind of "rag collection" "lumpensammlung") and later around the hal start. Both feel like related to irq/usb issues.

What is absolutely bad: the 500gib WDC Raid edition drive used to make 50-60 MB/s single on read&copy to raid0 and 35-45 MB/s on read&copy from raid0. The raid 0 is a 3xseagate barracuda 250gib raid0 notebook-like 3.5 half height drives on xf.

Processor/Ram: irrelevant. Even a 3800+ instead of 4400+ and DDR667 instead of DDR800 Ram (not that it would matter, cpu was never clocing up from 800 Mhz anyway on operations from/to raid an single disk). Now on intrepid I get 15-20 MB/s on this raid5 with almost always >= 2 GHz processor stepping up)
...

I go for interrupt problems.
The interrupt look like big unsolved conflicts to me.

In addition, remotely ssh-ing to another intrepid box (my htpc) i always get

(nautilus:18104): Eel-WARNING **: GConf-Fehler:
  Der Konfigurationsserver konnte nicht kontaktiert werden; mögliche Fehlerquellen sind, dass TCP/IP für ORBit nicht aktiviert ist oder auf Grund eines Systemabsturzes alte NFS-Sperren gesetzt sind. Unter http://www.gnome.org/projects/gconf/ erhalten Sie weitere Informationen (Details - 1: Verbindung zur Sitzung konnte nicht abgerufen werden: Failed to connect to socket /tmp/dbus-3hdoPHS2Ax: Connection refused)

--> probably one other separate bug. Strange, 3 months ago, intrepid alpha was just like hardy without no-go probs ;-)

This appears to be in the Ibex release, I just upgraded and it appears that in order to boot (laptop) I need to keep pressing a (any) button.

StatusWoe wrote:
> This appears to be in the Ibex release, I just upgraded and it appears
> that in order to boot (laptop) I need to keep pressing a (any) button.
>

yep. slightly less annoying workaround: at the 1st pause, unplug/plug in the AC
power. that keeps me from having to hold down a key for how ever long it takes
to boot.

I encounter exactly the same behavior as described by Grizzly with intrepid release on an Asus M2NPV (AMD Athlon Dual Core)

Just a few minutes after my last comment, I stumbled upon this thread:
http://backports.ubuntuforums.com/showthread.php?p=6036473
which, at least for me and probably Grizzly, includes the solution of the issue (tested on boot time, I have to do another shutdown after writing this :-)

I changed /etc/network/interfaces and commented out everything concerning a non-automatic configuration of eth0. Now it looks similar to this snippet:
auto eth0
# iface eth0 inet dhcp
# address 192.168.99.4
# netmask 255.255.255.0
# gateway 192.168.99.1

I had to leave the settings for the loopback device as they are, otherwise the nfsd hung in a timeout. You'll find the modified file attached.

(BTW: I guess, the gconf-error (described by Grizzly) has vanished, too, but I haven't memorized the way to reproduce it, so I'll just have to wait and see)

I Only have :
auto lo
iface lo inet loopback
I use the
And use: acpi=noirq on menu.lst
And work

Boot is fine with /etc/network/interfaces like:
auto lo
iface lo inet loopback
auto eth0

But the shutdown still hangs for some (long) time.

acpi=noirq makes no difference

Duplicated bug?
https://bugs.edge.launchpad.net/ubuntu/+source/linux/+bug/272247/

For the shutdown hang:
The chance it belongs to a network misconfiguration is very high, because when I switch off the router the PC is connected to, the PC almost immediately continues to shutdown.

Does this information helps someone to solve the issue?
Can I check another logfile to give some more information?

@p.tar - can you unload/deactivate/remove everything sensible related to the network, then see if the router on/off causes the same behavior.

On my box, having the laptop AC power adapter plugged in causes the "almost immediately continues to shutdown" which makes me think it is related to the signals that hardware send to say "I am plugged in."

In a few hours I will see if network cable makes a difference on my box.

@Carl: I'd like to, but I won't be able to try it before Sunday or Monday. Sorry!

Got a short moment:
I tried
sudo /etc/network/networking stop
which gave me
    Ignoring unknown interface eth0=eth0.

After googling for that, I changed /etc/network/interfaces (partly) from
   auto eth0
to
   auto eth0
   iface eth0 inet dhcp

With this configuration, I can (again) (re-)start the networking service.

I guess, the system will shutdown with the router still on. I'll report the behavior ASAP.

Wrong turn...

The boot delay came back, so I changed /e/n/interfaces back to auto eht0.

That is, the error message on /etc/init.d/networking stop or restart is still "Ignoring unknown interface eth0=eth0"

Switching off the router circumvents the problem, but it seems, just because of a broken process: I once saw an error message like "signal xy caught", when I switched off the router and (which happens occasionally at that point) the Ubuntu "shutdown progress bar" disappears to show the text output.

Any ideas?

Hi!
The initial bug still occures in 2.6.27-10. :-|
The "Kernel command line: root=UUID=b2d496e6-c1e8-4757-ace0-7fc94f74d199 ro acpi=debug noapictimer" still pauses for 13seconds on my Intel Core2 T5 based laptop. You can see it on dmesg:

[ 0.529159] ACPI: Using IOAPIC for interrupt routing
[ 0.529270] ACPI: EC: non-query interrupt received, switching to interrupt mode
[ 18.532867] ACPI: EC: GPE = 0x19, I/O: command/status = 0x66, data = 0x62
[ 18.532867] ACPI: EC: driver started in interrupt mode

I've attached dmesg,lspci and dmidecode to this report.
Stefan, do you have any ideas - I can use to prevent those behaviour?

Regards,
Martin

@Martin: At least the log you added does not seem to be from a run with noapictimer. If you could do and post the dmesg of two boots. Both with "apic=debug debug" (acpi=debug is ignored with the default kernel). For one add "noapictimer" for the other remove it. Then post both dmesg logs (if possible not compressed, just the plain files. makes it simpler to peek on them).
As for prevention: you could also play with "nohz=off" and "highres=off" at the cost of higher power usage. This worked for some. Or try the combination from the upstream bug "noapic lapic acpi=on" to see if that helps. Of course this still is no solution but collecting hints.

Hi!
I attached both versions boot parameters: 1st with "apic=debug debug noapictimer" and the second with "apic=debug debug" only.

Regards,
Martin

...my attachment - noapictimer disabled

regards

Maybe I suffered from a different bug, because the one I had encountered is gone with the latest Gnome update just a few days ago. That is, there's neither a delay on boot nor on shutdown anymore.

Thanks to the one who fixed it, who ever it was...

still happen with: 2.6.27-11-generic #1 SMP Fri Dec 19 16:29:35 UTC 2008 x86_64 GNU/Linux

2.6.28-4-generic from jaunty - no problem.

Carl,

could you please post dmesg?

Can I install 2.6.28-4-generic on Intrepid to solve tjis problem?

Looks like I spoke too soon. There is no pause when I boot the laptop with ac plugged in - dmesg of that is dmesg30ck.txt. previously, it would pause around 2.9 seconds, and I would un/re plug the ac and it would continune to boot.

If I boot with no AC, it pauses and I need to hit a key (including shift) or plug in AC. which is similar to before, but it seems to pause less. dmesg of that is dmesg31ck.txt

Hi,

I seem to have a similar problem, my system seems to hang at undefined moments during boot. Als I have the same hangs during normal system use, all hangs can be solved by pressing a random keyboard key I have included the dmesg log.

Here another dmesg I waited a little longer before pushing key this time....

Maybe the following can help, maybe not,

Some time ago I tried to boot haiku from my pc. Haiku failed during boot with a message saying it received a non maskable interrupt and that it could not continue.

Could ubuntu be fighting the same problem?

Best regards,

Joris

Also happen with Jaunty
 2.6.28-7-generic #20-Ubuntu SMP Mon Feb 9 15:42:34 UTC 2009 x86_64 GNU/Linux

Also Happen with jaunty
laptop 2.6.28-9-generic #31-Ubuntu SMP Wed Mar 11 15:43:49 UTC 2009 x86_64 GNU/Linux
works for both AC power but don't work for battery

Uname -a
Linux vnieto-laptop 2.6.28-10-generic #32-Ubuntu SMP Mon Mar 16 02:48:55 UTC 2009 x86_64 GNU/Linux

still happen:
With the power cable plug boot fine, very fine, but when I start or shutdown without ac power plug (with batteries) pausing during boot or shutdown

It looks like there may be a fix upstream in the form of commit a682604838763981613e42015cd0e39f2989d6bb "rcu: Teach RCU that idle task is not quiscent state at boot".

I've successfully back-ported the upstream commit to Jaunty, built and booted it. Because my systems don't exhibit this issue I'm going to pass the hard work of building some test kernels over to Stefan tomorrow.

Once he's built and published them hopefully we can get some test reports as to whether the issue has been at least partially resolved (there may be further work required).

Hi, sorry. It took me a while to get to the build. I placed the kernels that have TJ's RCU backport at http://people.ubuntu.com/~smb/bug254668/ Please have a try on them and report the outcome, thanks.

Latest upgrade of jaunty is still being affected by this bug.

Has anyone tested Stefan's kernel-builds referred to in comment #118 that have the RCU patch?

I've tested the patched kernel and it doesn't solve the bug. The results are the same as with the unpatched kernel.

It seems like the bug hasn't been solved in upstream yet.

I've just downloaded and compiled the git tree from Linus and the same problem, and others, happened.
Kernel version is 2.6.30 rc1.

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git

With 8.10 and a AMD Atlon 64 X2 TK-55 the same thing happens. With or without AC power.

I have not tried this in months, so no clue when it got fixed, but it seems to be fixed.

[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 2.6.31-13-generic (buildd@yellow) (gcc version 4.4.1 (Ubuntu 4.4.1-4ubuntu7) ) #44-Ubuntu SMP Sat Oct 10 15:27:14 UTC 2009 (Ubuntu 2.6.31-13.44-generic)
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-2.6.31-13-generic root=UUID=40833098-c247-4544-a426-9f9423bc562c ro quiet splash

...

[ 0.281198] ACPI: EC: Enabling special treatment for EC from MSI.
[ 0.281198] ACPI: EC: Look up EC in DSDT
[ 0.283672] ACPI: BIOS _OSI(Linux) query ignored
[ 0.284515] ACPI: Interpreter enabled
[ 0.284519] ACPI: (supports S0 S3 S4 S5)
[ 0.284540] ACPI: Using IOAPIC for interrupt routing
[ 0.281198] ACPI: EC: non-query interrupt received, switching to interrupt mode
[ 0.296046] ACPI: EC: GPE = 0x10, I/O: command/status = 0x66, data = 0x62
[ 0.296050] ACPI: EC: driver started in interrupt mode
[ 0.296361] ACPI: No dock devices found.
[ 0.296597] ACPI: PCI Root Bridge [PCI0] (0000:00)
[ 0.296667] pci 0000:00:01.1: reg 10 io port: [0x3080-0x30bf]
[ 0.296667] pci 0000:00:01.1: reg 20 io port: [0x3040-0x307f]
[ 0.296667] pci 0000:00:01.1: reg 24 io port: [0x3000-0x303f]
[ 0.296667] pci 0000:00:01.1: PME# supported from D3hot D3cold
[ 0.296667] pci 0000:00:01.1: PME# disabled

Hi Carl, while its good that this seems fixed, I am not sure whether the part
about the EC is the cause. From the many reports it seemed to get more and more
obvious that the IRQ override for IRQ0 is the common problem. So the ACPI BIOS
defines that the timer interrupt is connected to a different pin than 0
(usually 2) but in reality this is not true. AFAIK all the problems could be
worked around by using "acpi_skip_timer_override" on the command line. So maybe
there is an auto override ignore for certain hardware, now.

i had this problem on Debian, and i fixed with a .30 kernel, look here:
http://bugzilla.kernel.org/show_bug.cgi?id=13233

thanks!

Thanks Carl, so in your case the timer interrupt override is unchanged (which I know has been changed to ignore for some board vendors) but still the problem goes away. So the hint from Luis seems reasonable. Interestingly I believe I had tried those on a system locally and had not seen any change.
Be it as it is, Carl, as you are the initial submitter, you think we just go the pragmatic way and close this as fixed (even without ultimate prove on what exactly fixed it)?

This bug report was marked as Triaged a while ago but has not had any updated comments for quite some time. Please let us know if this issue remains in the current Ubuntu release, http://www.ubuntu.com/getubuntu/download . If the issue remains, click on the current status under the Status column and change the status back to "New". Thanks.

[This is an automated message. Apologies if it has reached you inappropriately; please just reply to this message indicating so.]

This bug was filed against a series that is no longer supported and so is being marked as Won't Fix. If this issue still exists in a supported series, please file a new bug.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.