LinuxLists.cc - Long timeout when booting >= 2.6.38

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Mon, 2011-05-02 at 20:49 +0200, Christian Hoffmann wrote:
> I have a strange hang/timeout when booting kernel 2.6.38 and newer. It
> hangs after a few initialization steps and then after 145 seconds, it
> continues to boot.
>
> I bisected kernel and found that offensive revision is:
>
> 08ec0c58fb8a05d3191d5cb6f5d6f81adb419798
> "x86: Improve TSC calibration using a delayed workqueue"
>
> Older kernels before above revision work fine.
>
> When passing acpi=off to kernel, the problem seems to disappear.

Hrm. So, on older kernels, what do you see from:
$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource

> Dmesg output below where you can see the jump from 1.47 to 146.85.
>
> The mainboard is an Asus M4A89GTD PRO/USB3 (latest BIOS revision).
>
> Kind regards,
> Chris
>
> PS: the problem has also been reported to ubuntu where more hw
> information is attached.
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/765230
> PSS: dmesg output

Hrm. The delay in the dmesg logs doesn't really seem to correlate that
closely with the delayed tsc calibration. Hrmm..

thanks
-john

2011-05-02 20:42:21

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

Hi,

> Hrm. So, on older kernels, what do you see from:
> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource

On older and newer kernel I see the same output:
$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc
$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc hpet acpi_pm

>
> Hrm. The delay in the dmesg logs doesn't really seem to correlate that
> closely with the delayed tsc calibration. Hrmm..
>

Maybe some side effect somehow. I can't explain.

Rgds,
Chris

2011-05-02 21:10:28

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 05/02/2011 10:42 PM, Christian Hoffmann wrote:
> Hi,
>
>> Hrm. So, on older kernels, what do you see from:
>> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
>> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
>
> On older and newer kernel I see the same output:
> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> tsc
> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> tsc hpet acpi_pm
>
>>
>> Hrm. The delay in the dmesg logs doesn't really seem to correlate that
>> closely with the delayed tsc calibration. Hrmm..

I also ran it now with calltrace_debug:

[ 1.451920] NET: Registered protocol family 2
[ 1.452077] IP route cache hash table entries: 262144 (order: 9,
2097152 bytes)
[ 1.453060] TCP established hash table entries: 524288 (order: 11,
8388608 bytes)
[ 1.454859] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
[ 1.455078] TCP: Hash tables configured (established 524288 bind 65536)
[ 1.455079] TCP reno registered
[ 1.455090] UDP hash table entries: 4096 (order: 5, 131072 bytes)
[ 1.455132] UDP-Lite hash table entries: 4096 (order: 5, 131072 bytes)
[ 1.455241] initcall inet_init+0x0/0x24a returned 0 after 3257 usecs
[ 1.455243] calling af_unix_init+0x0/0x55 @ 1
[ 1.455245] NET: Registered protocol family 1
[ 1.455251] initcall af_unix_init+0x0/0x55 returned 0 after 4 usecs
[ 1.455253] calling pci_apply_final_quirks+0x0/0x105 @ 1
[ 1.455259] pci 0000:00:01.0: MSI quirk detected; subordinate MSI
disabled
[ 146.830206] pci 0000:01:05.0: Boot video device
[ 146.830219] PCI: CLS 64 bytes, default 64
[ 146.830224] initcall pci_apply_final_quirks+0x0/0x105 returned 0
after 141967734 usecs
[ 146.830227] calling populate_rootfs+0x0/0x24 @ 1
[ 146.830231] initcall populate_rootfs+0x0/0x24 returned 801341486
after 0 usecs
[ 146.830233] initcall populate_rootfs+0x0/0x24 returned with error
code 801341486
[ 146.830236] calling pci_iommu_init+0x0/0x41 @ 1
[ 146.831483] PCI-DMA: Disabling AGP.
[ 146.831625] PCI-DMA: aperture base @ c4000000 size 65536 KB
[ 146.831627] PCI-DMA: using GART IOMMU.
[ 146.831629] PCI-DMA: Reserving 64MB of IOMMU area in the AGP aperture
[ 146.834920] initcall pci_iommu_init+0x0/0x41 returned 0 after 4571 usecs
[ 146.834924] calling calgary_fixup_tce_spaces+0x0/0xf0 @ 1
[ 146.834928] initcall calgary_fixup_tce_spaces+0x0/0xf0 returned -19
after 0 usecs
[ 146.834930] calling i8259A_init_sysfs+0x0/0x31 @ 1
[ 146.834949] initcall i8259A_init_sysfs+0x0/0x31 returned 0 after 15 usecs
[ 146.834951] calling vsyscall_init+0x0/0x66 @ 1
[ 146.835020] initcall vsyscall_init+0x0/0x66 returned 0 after 65 usecs
[ 146.835023] calling sbf_init+0x0/0xf4 @ 1
[ 146.835026] initcall sbf_init+0x0/0xf4 returned 0 after 0 usecs
[ 146.835028] calling i8237A_init_sysfs+0x0/0x22 @ 1
[ 146.835037] initcall i8237A_init_sysfs+0x0/0x22 returned 0 after 6 usecs
[ 146.835039] calling init_tsc_clocksource+0x0/0x5f @ 1
[ 146.835049] initcall init_tsc_clocksource+0x0/0x5f returned 0 after 6
usecs
[ 146.835051] calling add_rtc_cmos+0x0/0x96 @ 1
[ 146.835056] initcall add_rtc_cmos+0x0/0x96 returned 0 after 1 usecs
[ 146.835059] calling cache_sysfs_init+0x0/0x5e @ 1
[ 146.835292] initcall cache_sysfs_init+0x0/0x5e returned 0 after 225 usecs
[ 146.835295] calling mcheck_init_device+0x0/0xfd @ 1
[ 146.835422] initcall mcheck_init_device+0x0/0xfd returned 0 after 120
usecs
[ 146.835424] calling threshold_init_device+0x0/0x56 @ 1
[ 146.835480] initcall threshold_init_device+0x0/0x56 returned 0 after
51 usecs
[ 146.835483] calling thermal_throttle_init_device+0x0/0x9c @ 1

Rgds,
Chris

2011-05-02 21:49:21

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Mon, 2011-05-02 at 22:42 +0200, Christian Hoffmann wrote:
> Hi,
>
> > Hrm. So, on older kernels, what do you see from:
> > $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> > $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
>
> On older and newer kernel I see the same output:
> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> tsc
> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> tsc hpet acpi_pm

Can you reproduce the hang booting with "clocksource=hpet" and
"clocksource=acpi_pm" ?

thanks
-john

2011-05-02 22:13:03

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Mon, 2011-05-02 at 23:10 +0200, Christian Hoffmann wrote:
> >> Hrm. The delay in the dmesg logs doesn't really seem to correlate that
> >> closely with the delayed tsc calibration. Hrmm..
>
> I also ran it now with calltrace_debug:
[snip]
> [ 1.455253] calling pci_apply_final_quirks+0x0/0x105 @ 1
> [ 1.455259] pci 0000:00:01.0: MSI quirk detected; subordinate MSI
> disabled
> [ 146.830206] pci 0000:01:05.0: Boot video device
> [ 146.830219] PCI: CLS 64 bytes, default 64
> [ 146.830224] initcall pci_apply_final_quirks+0x0/0x105 returned 0
> after 141967734 usecs

Hrm.. Again, this looks more like something off with the MSI quirk bits.

I'm a little stumped right off how the refined calibration would impact
this. The only difference would be that the TSC clocksource isn't
registered at that point (because the refined calibration pushed the
registration back a bit), so you might be using the HPET at this point
instead of the TSC.

Let me know how the clocksource= boot bits changed things.

thanks
-john

2011-05-02 22:27:08

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 05/02/2011 11:49 PM, john stultz wrote:
> On Mon, 2011-05-02 at 22:42 +0200, Christian Hoffmann wrote:
>> Hi,
>>
>>> Hrm. So, on older kernels, what do you see from:
>>> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
>>> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
>>
>> On older and newer kernel I see the same output:
>> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
>> tsc
>> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
>> tsc hpet acpi_pm
>
> Can you reproduce the hang booting with "clocksource=hpet" and
> "clocksource=acpi_pm" ?

Both hang also.

Rgds,
Chris

2011-05-03 00:31:15

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Tue, 2011-05-03 at 00:27 +0200, Christian Hoffmann wrote:
> On 05/02/2011 11:49 PM, john stultz wrote:
> > On Mon, 2011-05-02 at 22:42 +0200, Christian Hoffmann wrote:
> >> Hi,
> >>
> >>> Hrm. So, on older kernels, what do you see from:
> >>> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> >>> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> >>
> >> On older and newer kernel I see the same output:
> >> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> >> tsc
> >> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> >> tsc hpet acpi_pm
> >
> > Can you reproduce the hang booting with "clocksource=hpet" and
> > "clocksource=acpi_pm" ?
>
> Both hang also.

Hm.. I wonder if the MSI quirk mucks up the hpet and acpi pm?

Could you send me the full dmesg output both with and without the
08ec0c58fb8a05d3191d5cb6f5d6f81adb419798 commit applied?

Also, does the same issue crop up if you compile the kernel with
CONFIG_PCI_MSI disabled?

thanks
-john

2011-05-03 18:32:27

by David R

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 02/05/11 19:49, Christian Hoffmann wrote:
> Hi all,
>
> I have a strange hang/timeout when booting kernel 2.6.38 and newer. It hangs after a few initialization steps and then after 145 seconds, it continues to boot.
>

fwiw, mine does pretty much the same... I've been ignoring it.

May 3 17:40:50 david kernel: [ 2.064787] system 00:0b: [io 0x0300-0x030f] has been reserved
May 3 17:40:50 david kernel: [ 2.064791] system 00:0b: [io 0x0a30-0x0a3f] has been reserved
May 3 17:40:50 david kernel: [ 2.064838] system 00:0c: [mem 0xe0000000-0xefffffff] has been reserved
May 3 17:40:50 david kernel: [ 2.064938] system 00:0d: [mem 0x00000000-0x0009ffff] could not be reserved
May 3 17:40:50 david kernel: [ 2.064940] system 00:0d: [mem 0x000c0000-0x000cffff] has been reserved
May 3 17:40:50 david kernel: [ 2.064942] system 00:0d: [mem 0x000e0000-0x000fffff] could not be reserved
May 3 17:40:50 david kernel: [ 2.064943] system 00:0d: [mem 0x00100000-0xdfffffff] could not be reserved
May 3 17:40:50 david kernel: [ 2.064945] system 00:0d: [mem 0xfec00000-0xffffffff] could not be reserved
May 3 17:40:50 david kernel: [ 2.065011] pnp: PnP ACPI: found 14 devices
May 3 17:40:50 david kernel: [ 2.065012] ACPI: ACPI bus type pnp unregistered
May 3 17:40:50 david kernel: [ 2.064327] Switched to NOHz mode on CPU #2
May 3 17:40:50 david kernel: [ 2.065566] Switched to NOHz mode on CPU #0
May 3 17:40:50 david kernel: [ 2.064334] Switched to NOHz mode on CPU #3
May 3 17:40:50 david kernel: [ 2.064338] Switched to NOHz mode on CPU #1
May 3 17:40:50 david kernel: [ 2.068059] pci 0000:00:01.0: PCI bridge to [bus 01-01]
May 3 17:40:50 david kernel: [ 2.068061] pci 0000:00:01.0: bridge window [io 0xc000-0xcfff]
May 3 17:40:50 david kernel: [ 2.068064] pci 0000:00:01.0: bridge window [mem 0xfe800000-0xfe9fffff]
May 3 17:40:50 david kernel: [ 2.068066] pci 0000:00:01.0: bridge window [mem 0xf0000000-0xf7ffffff 64bit pref]
May 3 17:40:50 david kernel: [ 2.068069] pci 0000:00:0a.0: PCI bridge to [bus 02-02]
May 3 17:40:50 david kernel: [ 2.068070] pci 0000:00:0a.0: bridge window [io 0xd000-0xdfff]
May 3 17:40:50 david kernel: [ 2.068073] pci 0000:00:0a.0: bridge window [mem 0xfea00000-0xfeafffff]
May 3 17:40:50 david kernel: [ 2.068075] pci 0000:00:0a.0: bridge window [mem 0xfdf00000-0xfdffffff 64bit pref]
May 3 17:40:50 david kernel: [ 2.068078] pci 0000:00:14.4: PCI bridge to [bus 03-03]
May 3 17:40:50 david kernel: [ 2.068080] pci 0000:00:14.4: bridge window [io 0xe000-0xefff]
May 3 17:40:50 david kernel: [ 2.068084] pci 0000:00:14.4: bridge window [mem 0xfeb00000-0xfebfffff]
May 3 17:40:50 david kernel: [ 2.068088] pci 0000:00:14.4: bridge window [mem pref disabled]
May 3 17:40:50 david kernel: [ 2.068102] pci 0000:00:0a.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18
May 3 17:40:50 david kernel: [ 2.068155] NET: Registered protocol family 2
May 3 17:40:50 david kernel: [ 2.068243] IP route cache hash table entries: 131072 (order: 8, 1048576 bytes)
May 3 17:40:50 david kernel: [ 2.068926] TCP established hash table entries: 524288 (order: 11, 8388608 bytes)
May 3 17:40:50 david kernel: [ 2.070825] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
May 3 17:40:50 david kernel: [ 2.071064] TCP: Hash tables configured (established 524288 bind 65536)
May 3 17:40:50 david kernel: [ 2.071066] TCP reno registered
May 3 17:40:50 david kernel: [ 2.071073] UDP hash table entries: 2048 (order: 4, 65536 bytes)
May 3 17:40:50 david kernel: [ 2.071095] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
May 3 17:40:50 david kernel: [ 2.071183] NET: Registered protocol family 1
May 3 17:40:50 david kernel: [ 2.071192] pci 0000:00:01.0: MSI quirk detected; subordinate MSI disabled
May 3 17:40:50 david kernel: [ 147.471348] PCI-DMA: Disabling AGP.
May 3 17:40:50 david kernel: [ 147.471436] PCI-DMA: aperture base @ c0000000 size 65536 KB
May 3 17:40:50 david kernel: [ 147.471437] PCI-DMA: using GART IOMMU.
May 3 17:40:50 david kernel: [ 147.471439] PCI-DMA: Reserving 64MB of IOMMU area in the AGP aperture
May 3 17:40:50 david kernel: [ 147.474743] audit: initializing netlink socket (disabled)
May 3 17:40:50 david kernel: [ 147.474756] type=2000 audit(1304440837.469:1): initialized
May 3 17:40:50 david kernel: [ 147.490902] HugeTLB registered 2 MB page size, pre-allocated 0 pages
May 3 17:40:50 david kernel: [ 147.491941] VFS: Disk quotas dquot_6.5.2
May 3 17:40:50 david kernel: [ 147.491973] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
May 3 17:40:50 david kernel: [ 147.492452] fuse init (API version 7.16)
May 3 17:40:50 david kernel: [ 147.492512] msgmni has been set to 7920
May 3 17:40:50 david kernel: [ 147.492744] io scheduler noop registered
May 3 17:40:50 david kernel: [ 147.492745] io scheduler deadline registered
May 3 17:40:50 david kernel: [ 147.492768] io scheduler cfq registered (default)
May 3 17:40:50 david kernel: [ 147.492968] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
May 3 17:40:50 david kernel: [ 147.492983] pciehp: PCI Express Hot Plug Controller Driver version: 0.4

2011-05-03 19:33:06

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

Hi,

> Hm.. I wonder if the MSI quirk mucks up the hpet and acpi pm?
>
> Could you send me the full dmesg output both with and without the
> 08ec0c58fb8a05d3191d5cb6f5d6f81adb419798 commit applied?

Here we go:

Working (08ec0c58fb8a05d3191d5cb6f5d6f81adb419798 - 1)
http://pastebin.com/hwYnBZrC

Not working (08ec0c58fb8a05d3191d5cb6f5d6f81adb419798)
http://pastebin.com/i1GaxeXk

> Also, does the same issue crop up if you compile the kernel with
> CONFIG_PCI_MSI disabled?

I don't seem to be able to switch that off. It gets reset when building
the kernel (dependencies?). I then tried to use kernel param pci=nomsi,
but the problem persists.

Rgds,
Chris

2011-05-04 01:00:48

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Tue, 2011-05-03 at 00:27 +0200, Christian Hoffmann wrote:
> On 05/02/2011 11:49 PM, john stultz wrote:
> > On Mon, 2011-05-02 at 22:42 +0200, Christian Hoffmann wrote:
> >> Hi,
> >>
> >>> Hrm. So, on older kernels, what do you see from:
> >>> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> >>> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> >>
> >> On older and newer kernel I see the same output:
> >> $ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> >> tsc
> >> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> >> tsc hpet acpi_pm
> >
> > Can you reproduce the hang booting with "clocksource=hpet" and
> > "clocksource=acpi_pm" ?
>
> Both hang also.

Sorry, one more clarifying point here:

When you used either clocksource=hpet/clocksource=acpi_pm did the
behavior of the system seem different after booting? In other words:
does running time waiting a few seconds and then running time again show
the expected passage of time? Were any following hangs seen, or was it
only the first one at boot?

thanks
-john

2011-05-04 01:39:06

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Tue, 2011-05-03 at 20:48 +0200, Christian Hoffmann wrote:
> Hi,
>
> > Could you send me the full dmesg output both with and without the
> > 08ec0c58fb8a05d3191d5cb6f5d6f81adb419798 commit applied?
>
> broken.dmesg is kernel at 08ec0c58fb8a05d3191d5cb6f5d6f81adb419798
> working.dmesg is 08ec0c58fb8a05d3191d5cb6f5d6f81adb419798 - 1
>
> >
> > Also, does the same issue crop up if you compile the kernel with
> > CONFIG_PCI_MSI disabled?
> >
>
> I can't really disable this, can I? This gets set by other presets. I
> tried to use pci=nomsi, but i see same issue (but I also see the MSI
> quirks in dmesg, so not sure if this is working).
>
> I didn't cc the linux-kernel, as I don't know if I am supposed to post
> dmesg/attachements.

Can you send dmesg on a broken kernel with the following patch added?

diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
index 5129ed6..6718e7f 100644
--- a/drivers/pci/quirks.c
+++ b/drivers/pci/quirks.c
@@ -2791,6 +2791,7 @@ static void pci_do_fixups(struct pci_dev *dev, struct pci_fixup *f,
if ((f->vendor == dev->vendor || f->vendor == (u16) PCI_ANY_ID) &&
(f->device == dev->device || f->device == (u16) PCI_ANY_ID)) {
dev_dbg(&dev->dev, "calling %pF\n", f->hook);
+ printk("Calling fixup hook: %pF\n", f->hook);
f->hook(dev);
}
f++;

2011-05-04 07:12:44

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

> Can you send dmesg on a broken kernel with the following patch added?
>
> diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
> index 5129ed6..6718e7f 100644
> --- a/drivers/pci/quirks.c
> +++ b/drivers/pci/quirks.c
> @@ -2791,6 +2791,7 @@ static void pci_do_fixups(struct pci_dev *dev, struct pci_fixup *f,
> if ((f->vendor == dev->vendor || f->vendor == (u16) PCI_ANY_ID)&&
> (f->device == dev->device || f->device == (u16) PCI_ANY_ID)) {
> dev_dbg(&dev->dev, "calling %pF\n", f->hook);
> + printk("Calling fixup hook: %pF\n", f->hook);
> f->hook(dev);
> }
> f++;

Hi,

dmesg output with patch applied can be found here:

http://pastebin.com/raw.php?i=y6gC848k

Rgds,
Chris

2011-05-04 07:31:34

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 05/04/2011 03:00 AM, john stultz wrote:
> On Tue, 2011-05-03 at 00:27 +0200, Christian Hoffmann wrote:
>>>
>>> Can you reproduce the hang booting with "clocksource=hpet" and
>>> "clocksource=acpi_pm" ?
>>
>> Both hang also.
>
> Sorry, one more clarifying point here:
>
> When you used either clocksource=hpet/clocksource=acpi_pm did the
> behavior of the system seem different after booting? In other words:
> does running time waiting a few seconds and then running time again show
> the expected passage of time? Were any following hangs seen, or was it
> only the first one at boot?

Hi,

with hpet no problems seen. No further hangs either.

In fact, switching to acpi_pm doesn't seem to work:

$ dmesg | grep clock

[ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
[ 0.000000] Kernel command line:
BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+ root=/dev/mapper/vg-root ro
quiet splash vt.handoff=7 clocksource=acpi_pm
[ 0.000000] hpet clockevent registered
[ 1.413835] Switching to clocksource hpet
[ 1.420762] Override clocksource acpi_pm is not HRT compatible.
Cannot switch while in HRT/NOHZ mode
[ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
[ 147.940147] Switching to clocksource tsc

Regards,
Chris

2011-05-04 08:37:49

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Wed, 4 May 2011, Christian Hoffmann wrote:

> In fact, switching to acpi_pm doesn't seem to work:
>
> $ dmesg | grep clock
>
> [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 0.000000] hpet clockevent registered
> [ 1.413835] Switching to clocksource hpet
> [ 1.420762] Override clocksource acpi_pm is not HRT compatible. Cannot
> switch while in HRT/NOHZ mode

Huch. There is something badly wrong. Can you provide the output of

cat /sys/devices/system/clocksource/clocksource0/available_clocksource

please ?

> [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
> [ 147.940147] Switching to clocksource tsc

I just looked at the two boot logs you provided. So the main
difference is that TSC gets installed way later.

Can you please boot the "working" kernel with clocksource=hpet on the
commandline and verify whether the boot hang appears there as well?

Thanks,

tglx

2011-05-04 16:47:51

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

Hi,

> Huch. There is something badly wrong. Can you provide the output of
>
> cat /sys/devices/system/clocksource/clocksource0/available_clocksource
>
> please ?

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc hpet acpi_pm

>
>> [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
>> [ 147.940147] Switching to clocksource tsc
>
> I just looked at the two boot logs you provided. So the main
> difference is that TSC gets installed way later.
>
> Can you please boot the "working" kernel with clocksource=hpet on the
> commandline and verify whether the boot hang appears there as well?
>

No, it works fine. See http://pastebin.com/raw.php?i=4wJWkiNM.

Rgds,
Chris

2011-05-04 17:04:34

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 05/04/2011 09:12 AM, Christian Hoffmann wrote:
>
>> Can you send dmesg on a broken kernel with the following patch added?
>>
>> diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
>> index 5129ed6..6718e7f 100644
>> --- a/drivers/pci/quirks.c
>> +++ b/drivers/pci/quirks.c
>> @@ -2791,6 +2791,7 @@ static void pci_do_fixups(struct pci_dev *dev,
>> struct pci_fixup *f,
>> if ((f->vendor == dev->vendor || f->vendor == (u16) PCI_ANY_ID)&&
>> (f->device == dev->device || f->device == (u16) PCI_ANY_ID)) {
>> dev_dbg(&dev->dev, "calling %pF\n", f->hook);
>> + printk("Calling fixup hook: %pF\n", f->hook);
>> f->hook(dev);
>> }
>> f++;
>
> Hi,
>
> dmesg output with patch applied can be found here:
>
> http://pastebin.com/raw.php?i=y6gC848k

As it "works" with acpi=off, I put the dmesg output of same "broken"
kernel with acpi_off here:

http://pastebin.com/raw.php?i=yBGNL8f2

And
cat /sys/devices/system/clocksource/clocksource0/available_clocksource
jiffies tsc

Rgds,
Chris

2011-05-04 17:49:23

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Wed, 4 May 2011, Christian Hoffmann wrote:
> Hi,
>
> > Huch. There is something badly wrong. Can you provide the output of
> >
> > cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> >
> > please ?
>
> $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> tsc hpet acpi_pm

Hmm. So I really wonder why it refuses to switch to acpi_pm when you
select it on the kernel command line.

Does "echo acpi_pm > /sys/devices/system/clocksource/clocksource0/current_clocksource"
work ?

> > > [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
> > > [ 147.940147] Switching to clocksource tsc
> >
> > I just looked at the two boot logs you provided. So the main
> > difference is that TSC gets installed way later.
> >
> > Can you please boot the "working" kernel with clocksource=hpet on the
> > commandline and verify whether the boot hang appears there as well?
> >
>
> No, it works fine. See http://pastebin.com/raw.php?i=4wJWkiNM.

Ok. That excludes HPET. So the only difference left is the late
registration of TSC which happens _AFTER_ the hang.

Can you boot the non working kernel with "lpj=28098860" on the kernel
command line ?

Thanks,

tglx

2011-05-04 19:40:17

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

>
> Hmm. So I really wonder why it refuses to switch to acpi_pm when you
> select it on the kernel command line.
>
> Does "echo acpi_pm> /sys/devices/system/clocksource/clocksource0/current_clocksource"
> work ?

Yes, that seems to work:

root@c3po:~# echo acpi_pm >
/sys/devices/system/clocksource/clocksource0/current_clocksource
root@c3po:~# dmesg | grep clocksource
[ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch+
root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
[ 0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch+
root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
[ 1.463754] Switching to clocksource tsc
[ 1.470700] Override clocksource acpi_pm is not HRT compatible.
Cannot switch while in HRT/NOHZ mode
[ 125.808622] Switching to clocksource acpi_pm

>
> Ok. That excludes HPET. So the only difference left is the late
> registration of TSC which happens _AFTER_ the hang.
>
> Can you boot the non working kernel with "lpj=28098860" on the kernel
> command line ?

The dmesg output with lpj is here (and it still hangs):

http://pastebin.com/raw.php?i=wZWrbc7Z

Kind regards,

Chris

2011-05-04 20:53:16

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Wed, 4 May 2011, Christian Hoffmann wrote:

> >
> > Hmm. So I really wonder why it refuses to switch to acpi_pm when you
> > select it on the kernel command line.
> >
> > Does "echo acpi_pm>
> > /sys/devices/system/clocksource/clocksource0/current_clocksource"
> > work ?
>
> Yes, that seems to work:
>
> root@c3po:~# echo acpi_pm >
> /sys/devices/system/clocksource/clocksource0/current_clocksource
> root@c3po:~# dmesg | grep clocksource
> [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch+
> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch+
> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 1.463754] Switching to clocksource tsc
> [ 1.470700] Override clocksource acpi_pm is not HRT compatible. Cannot
> switch while in HRT/NOHZ mode

Weird, I think it's unrelated to the hang, but still something which
wants to be investigated.

> [ 125.808622] Switching to clocksource acpi_pm

At least that works :)

> >
> > Ok. That excludes HPET. So the only difference left is the late
> > registration of TSC which happens _AFTER_ the hang.
> >
> > Can you boot the non working kernel with "lpj=28098860" on the kernel
> > command line ?
>
> The dmesg output with lpj is here (and it still hangs):
>
> http://pastebin.com/raw.php?i=wZWrbc7Z

That excludes some odd interaction with the udelay code.

So we are back to:

[ 0.644189] Calling fixup hook: quirk_usb_early_handoff+0x0/0x4a6
[ 145.936254] Calling fixup hook: pci_fixup_video+0x0/0xac

So we really need to know what's happening there.

Can you please apply the following patch and enable
CONFIG_FUNCTION_TRACER and add "ftrace=function" on the command line?

When the box is up, mount debugfs (mount -t debugfs debugfs
/sys/kernel/debug) and read out /sys/kernel/debug/tracing/trace, bzip2
it and provide it somewhere for download. If you have no way to do
that, mail it to me offlist.

Thanks,

tglx

--- linux-2.6.orig/drivers/pci/quirks.c
+++ linux-2.6/drivers/pci/quirks.c
@@ -2787,11 +2787,17 @@ DECLARE_PCI_FIXUP_EARLY(PCI_VENDOR_ID_IN
static void pci_do_fixups(struct pci_dev *dev, struct pci_fixup *f,
struct pci_fixup *end)
{
+ u64 t1, t2;
+
while (f < end) {
if ((f->vendor == dev->vendor || f->vendor == (u16) PCI_ANY_ID) &&
(f->device == dev->device || f->device == (u16) PCI_ANY_ID)) {
dev_dbg(&dev->dev, "calling %pF\n", f->hook);
+ t1 = sched_clock();
f->hook(dev);
+ t2 = sched_clock();
+ if ((t2 - t1) > NSEC_PER_SEC)
+ tracing_off();
}
f++;
}

2011-05-05 01:16:58

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Wed, 2011-05-04 at 09:31 +0200, Christian Hoffmann wrote:
> In fact, switching to acpi_pm doesn't seem to work:
>
> $ dmesg | grep clock
>
> [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 0.000000] Kernel command line:
> BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+ root=/dev/mapper/vg-root ro
> quiet splash vt.handoff=7 clocksource=acpi_pm
> [ 0.000000] hpet clockevent registered
> [ 1.413835] Switching to clocksource hpet
> [ 1.420762] Override clocksource acpi_pm is not HRT compatible.
> Cannot switch while in HRT/NOHZ mode
> [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
> [ 147.940147] Switching to clocksource tsc

So I think I've sorted this out.

The watchdog code is what enables CLOCK_SOURCE_VALID_FOR_HRES, but we
actually end up selecting the clocksource before we enqueue it into the
watchdog list, so that's why we see the warning.

I suspect the following will resolve this detail.

Signed-off-by: John Stultz <[email protected]>

diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
index 6519cf6..0e17c10 100644
--- a/kernel/time/clocksource.c
+++ b/kernel/time/clocksource.c
@@ -685,8 +685,8 @@ int __clocksource_register_scale(struct clocksource *cs, u32 scale, u32 freq)
/* Add clocksource to the clcoksource list */
mutex_lock(&clocksource_mutex);
clocksource_enqueue(cs);
- clocksource_select();
clocksource_enqueue_watchdog(cs);
+ clocksource_select();
mutex_unlock(&clocksource_mutex);
return 0;
}
@@ -706,8 +706,8 @@ int clocksource_register(struct clocksource *cs)

mutex_lock(&clocksource_mutex);
clocksource_enqueue(cs);
- clocksource_select();
clocksource_enqueue_watchdog(cs);
+ clocksource_select();
mutex_unlock(&clocksource_mutex);
return 0;
}

2011-05-05 08:26:10

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Wed, 4 May 2011, john stultz wrote:

> On Wed, 2011-05-04 at 09:31 +0200, Christian Hoffmann wrote:
> > In fact, switching to acpi_pm doesn't seem to work:
> >
> > $ dmesg | grep clock
> >
> > [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
> > root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
> > [ 0.000000] Kernel command line:
> > BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+ root=/dev/mapper/vg-root ro
> > quiet splash vt.handoff=7 clocksource=acpi_pm
> > [ 0.000000] hpet clockevent registered
> > [ 1.413835] Switching to clocksource hpet
> > [ 1.420762] Override clocksource acpi_pm is not HRT compatible.
> > Cannot switch while in HRT/NOHZ mode
> > [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
> > [ 147.940147] Switching to clocksource tsc
>
> So I think I've sorted this out.
>
> The watchdog code is what enables CLOCK_SOURCE_VALID_FOR_HRES, but we
> actually end up selecting the clocksource before we enqueue it into the
> watchdog list, so that's why we see the warning.
>
> I suspect the following will resolve this detail.

It does. Good catch!

> Signed-off-by: John Stultz <[email protected]>
>
> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
> index 6519cf6..0e17c10 100644
> --- a/kernel/time/clocksource.c
> +++ b/kernel/time/clocksource.c
> @@ -685,8 +685,8 @@ int __clocksource_register_scale(struct clocksource *cs, u32 scale, u32 freq)
> /* Add clocksource to the clcoksource list */
> mutex_lock(&clocksource_mutex);
> clocksource_enqueue(cs);
> - clocksource_select();
> clocksource_enqueue_watchdog(cs);
> + clocksource_select();
> mutex_unlock(&clocksource_mutex);
> return 0;
> }
> @@ -706,8 +706,8 @@ int clocksource_register(struct clocksource *cs)
>
> mutex_lock(&clocksource_mutex);
> clocksource_enqueue(cs);
> - clocksource_select();
> clocksource_enqueue_watchdog(cs);
> + clocksource_select();
> mutex_unlock(&clocksource_mutex);
> return 0;
> }
>
>
>

2011-05-05 17:28:18

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

>
> So we are back to:
>
> [ 0.644189] Calling fixup hook: quirk_usb_early_handoff+0x0/0x4a6
> [ 145.936254] Calling fixup hook: pci_fixup_video+0x0/0xac
>
> So we really need to know what's happening there.
>
> Can you please apply the following patch and enable
> CONFIG_FUNCTION_TRACER and add "ftrace=function" on the command line?
>
> When the box is up, mount debugfs (mount -t debugfs debugfs
> /sys/kernel/debug) and read out /sys/kernel/debug/tracing/trace, bzip2
> it and provide it somewhere for download. If you have no way to do
> that, mail it to me offlist.

Hi,

trace can be found here:

http://dl.dropbox.com/u/21820416/hanging_2.6.39-rc6.trace.bz2

Rgds,
Chris

2011-05-05 17:47:11

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On 05/05/2011 10:25 AM, Thomas Gleixner wrote:
> On Wed, 4 May 2011, john stultz wrote:
>
>> On Wed, 2011-05-04 at 09:31 +0200, Christian Hoffmann wrote:
>>> In fact, switching to acpi_pm doesn't seem to work:
>>>
>>> $ dmesg | grep clock
>>>
>>> [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+
>>> root=/dev/mapper/vg-root ro quiet splash vt.handoff=7 clocksource=acpi_pm
>>> [ 0.000000] Kernel command line:
>>> BOOT_IMAGE=/vmlinuz-2.6.39-rc5-ch-broken+ root=/dev/mapper/vg-root ro
>>> quiet splash vt.handoff=7 clocksource=acpi_pm
>>> [ 0.000000] hpet clockevent registered
>>> [ 1.413835] Switching to clocksource hpet
>>> [ 1.420762] Override clocksource acpi_pm is not HRT compatible.
>>> Cannot switch while in HRT/NOHZ mode
>>> [ 147.940143] Refined TSC clocksource calibration: 2809.409 MHz.
>>> [ 147.940147] Switching to clocksource tsc
>>
>> So I think I've sorted this out.
>>
>> The watchdog code is what enables CLOCK_SOURCE_VALID_FOR_HRES, but we
>> actually end up selecting the clocksource before we enqueue it into the
>> watchdog list, so that's why we see the warning.
>>
>> I suspect the following will resolve this detail.
>
> It does. Good catch!
>
>> Signed-off-by: John Stultz<[email protected]>
>>
>> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
>> index 6519cf6..0e17c10 100644
>> --- a/kernel/time/clocksource.c
>> +++ b/kernel/time/clocksource.c
>> @@ -685,8 +685,8 @@ int __clocksource_register_scale(struct clocksource *cs, u32 scale, u32 freq)
>> /* Add clocksource to the clcoksource list */
>> mutex_lock(&clocksource_mutex);
>> clocksource_enqueue(cs);
>> - clocksource_select();
>> clocksource_enqueue_watchdog(cs);
>> + clocksource_select();
>> mutex_unlock(&clocksource_mutex);
>> return 0;
>> }
>> @@ -706,8 +706,8 @@ int clocksource_register(struct clocksource *cs)
>>
>> mutex_lock(&clocksource_mutex);
>> clocksource_enqueue(cs);
>> - clocksource_select();
>> clocksource_enqueue_watchdog(cs);
>> + clocksource_select();
>> mutex_unlock(&clocksource_mutex);
>> return 0;
>> }
>>

I can now select clocksource=acpi_pm as kernel parameter. The boot still
hangs after "MSI quirk detected...", but the timestamps in dmesg don't
show the jump anymore.

[ 1.426107] NET: Registered protocol family 1
[ 1.426162] pci 0000:00:01.0: MSI quirk detected; subordinate MSI
disabled
[ 2.300212] pci 0000:01:05.0: Boot video device
[ 2.300226] PCI: CLS 64 bytes, default 64

Full dmesg is here:
http://pastebin.com/raw.php?i=3Fctvsrp

Rgds,
Chris

2011-05-05 18:41:22

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Thu, 5 May 2011, Christian Hoffmann wrote:
> On 05/05/2011 10:25 AM, Thomas Gleixner wrote:
> I can now select clocksource=acpi_pm as kernel parameter. The boot still hangs
> after "MSI quirk detected...", but the timestamps in dmesg don't show the jump
> anymore.
>
> [ 1.426107] NET: Registered protocol family 1
> [ 1.426162] pci 0000:00:01.0: MSI quirk detected; subordinate MSI disabled
> [ 2.300212] pci 0000:01:05.0: Boot video device
> [ 2.300226] PCI: CLS 64 bytes, default 64

That's because pmtimer wraps around several times in 140 seconds :)

Thanks,

tglx

2011-05-09 08:22:48

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Thu, 5 May 2011, Christian Hoffmann wrote:

> >
> > So we are back to:
> >
> > [ 0.644189] Calling fixup hook: quirk_usb_early_handoff+0x0/0x4a6
> > [ 145.936254] Calling fixup hook: pci_fixup_video+0x0/0xac
> >
> > So we really need to know what's happening there.
> >
> > Can you please apply the following patch and enable
> > CONFIG_FUNCTION_TRACER and add "ftrace=function" on the command line?
> >
> > When the box is up, mount debugfs (mount -t debugfs debugfs
> > /sys/kernel/debug) and read out /sys/kernel/debug/tracing/trace, bzip2
> > it and provide it somewhere for download. If you have no way to do
> > that, mail it to me offlist.
>
> Hi,
>
> trace can be found here:
>
> http://dl.dropbox.com/u/21820416/hanging_2.6.39-rc6.trace.bz2

Thanks, can you please add the following patch and generate another
trace ?

Thanks,

Thomas

--- linux-2.6.orig/kernel/timer.c
+++ linux-2.6/kernel/timer.c
@@ -1268,11 +1268,14 @@ unsigned long get_next_timer_interrupt(u
if (cpu_is_offline(smp_processor_id()))
return now + NEXT_TIMER_MAX_DELTA;
spin_lock(&base->lock);
+ trace_printk("nx: %lx tj: %lx\n", base->next_timer, base->timer_jiffies);
if (time_before_eq(base->next_timer, base->timer_jiffies))
base->next_timer = __next_timer_interrupt(base);
expires = base->next_timer;
spin_unlock(&base->lock);

+ trace_printk("ex: %lx nw: %lx\n", expires, now);
+
if (time_before_eq(expires, now))
return now;

2011-05-15 20:11:18

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

> Thanks, can you please add the following patch and generate another
> trace ?
>
> Thanks,
>
> Thomas
>
> --- linux-2.6.orig/kernel/timer.c
> +++ linux-2.6/kernel/timer.c
> @@ -1268,11 +1268,14 @@ unsigned long get_next_timer_interrupt(u
> if (cpu_is_offline(smp_processor_id()))
> return now + NEXT_TIMER_MAX_DELTA;
> spin_lock(&base->lock);
> + trace_printk("nx: %lx tj: %lx\n", base->next_timer, base->timer_jiffies);
> if (time_before_eq(base->next_timer, base->timer_jiffies))
> base->next_timer = __next_timer_interrupt(base);
> expires = base->next_timer;
> spin_unlock(&base->lock);
>
> + trace_printk("ex: %lx nw: %lx\n", expires, now);
> +
> if (time_before_eq(expires, now))
> return now;
>

Hi,

new trace:
http://dl.dropbox.com/u/21820416/traceing2.log.bz2

Sorry for delay.

Regards,
Chris

2011-05-16 09:07:54

[permalink] [raw]

Subject: Re: Long timeout when booting >= 2.6.38

On Sun, 15 May 2011, Christian Hoffmann wrote:
> new trace:
> http://dl.dropbox.com/u/21820416/traceing2.log.bz2
>
> Sorry for delay.

Nothing to be sorry about. Thanks for providing the information. If I
decoded the problem correctly then this just unearthed a real long
standing bug. Does the patch below solve the problem ?

Thanks,

tglx

--- linux-2.6.orig/kernel/time/tick-broadcast.c
+++ linux-2.6/kernel/time/tick-broadcast.c
@@ -522,10 +522,11 @@ static void tick_broadcast_init_next_eve
*/
void tick_broadcast_setup_oneshot(struct clock_event_device *bc)
{
+ int cpu = smp_processor_id();
+
/* Set it up only once ! */
if (bc->event_handler != tick_handle_oneshot_broadcast) {
int was_periodic = bc->mode == CLOCK_EVT_MODE_PERIODIC;
- int cpu = smp_processor_id();

bc->event_handler = tick_handle_oneshot_broadcast;
clockevents_set_mode(bc, CLOCK_EVT_MODE_ONESHOT);
@@ -551,6 +552,15 @@ void tick_broadcast_setup_oneshot(struct
tick_broadcast_set_event(tick_next_period, 1);
} else
bc->next_event.tv64 = KTIME_MAX;
+ } else {
+ /*
+ * The first cpu which switches to oneshot mode sets
+ * the bit for all other cpus which are in the general
+ * (periodic) broadcast mask. So the bit is set and
+ * would prevent the first broadcast enter after this
+ * to program the bc device.
+ */
+ tick_broadcast_clear_oneshot(cpu);
}
}

2011-05-16 19:34:59