2013-09-12 04:58:36

by Tang Chen

[permalink] [raw]
Subject: [Bug report] Warning when hot-add an ACPI0004 device.

Hi Rafael, Toshi,

When we hot-add an ACPI0004 device, we got the following warning:

acpi ACPI0004:01: Attempt to re-insert

The ACPI0004 device is a System Board in Fujitsu server, which has two
numa nodes (processors and memory).

It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
acpi_hotplug_notify_cb().


According to bisect, this happens after the following commit:

From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
From: "Rafael J. Wysocki" <[email protected]>
Date: Sun, 3 Mar 2013 23:05:55 +0100
Subject: [PATCH 1/1] ACPI / container: Use common hotplug code

Switch the ACPI container driver to using common device hotplug code
introduced previously. This reduces the driver down to a trivial
definition and registration of a struct acpi_scan_handler object.

Signed-off-by: Rafael J. Wysocki <[email protected]>
Acked-by: Toshi Kani <[email protected]>
Tested-by: Toshi Kani <[email protected]>
---
drivers/acpi/container.c | 146
++++-------------------------------------------
1 file changed, 10 insertions(+), 136 deletions(-)


I'm now investigating this problem. If you have any idea about why this
happens, please let me know.

Thanks. :)


2013-09-12 15:13:56

by Toshi Kani

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
> Hi Rafael, Toshi,
>
> When we hot-add an ACPI0004 device, we got the following warning:
>
> acpi ACPI0004:01: Attempt to re-insert
>
> The ACPI0004 device is a System Board in Fujitsu server, which has two
> numa nodes (processors and memory).
>
> It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
> acpi_hotplug_notify_cb().
>
>
> According to bisect, this happens after the following commit:
>
> From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
> From: "Rafael J. Wysocki" <[email protected]>
> Date: Sun, 3 Mar 2013 23:05:55 +0100
> Subject: [PATCH 1/1] ACPI / container: Use common hotplug code
>
> Switch the ACPI container driver to using common device hotplug code
> introduced previously. This reduces the driver down to a trivial
> definition and registration of a struct acpi_scan_handler object.
>
> Signed-off-by: Rafael J. Wysocki <[email protected]>
> Acked-by: Toshi Kani <[email protected]>
> Tested-by: Toshi Kani <[email protected]>
> ---
> drivers/acpi/container.c | 146
> ++++-------------------------------------------
> 1 file changed, 10 insertions(+), 136 deletions(-)
>
>
> I'm now investigating this problem. If you have any idea about why this
> happens, please let me know.

With the above change, container devices use the common notify handler,
which logs the warning message in question when it receives device check
twice on a same device. Before the change, the container-specific
notify handler did not log this message in the same case (but considered
it as an eject request).

So, I suspect that you are getting device check twice regardless of the
kernel change. Can you check KERN_DEBUG messages to see if that is the
case? The notify handler logs all events with KERN_DEBUG.

Thanks,
-Toshi

2013-09-25 10:36:13

by Gu Zheng

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

Hi Toshi,

On 09/12/2013 11:11 PM, Toshi Kani wrote:

> On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
>> Hi Rafael, Toshi,
>>
>> When we hot-add an ACPI0004 device, we got the following warning:
>>
>> acpi ACPI0004:01: Attempt to re-insert
>>
>> The ACPI0004 device is a System Board in Fujitsu server, which has two
>> numa nodes (processors and memory).
>>
>> It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
>> acpi_hotplug_notify_cb().
>>
>>
>> According to bisect, this happens after the following commit:
>>
>> From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
>> From: "Rafael J. Wysocki" <[email protected]>
>> Date: Sun, 3 Mar 2013 23:05:55 +0100
>> Subject: [PATCH 1/1] ACPI / container: Use common hotplug code
>>
>> Switch the ACPI container driver to using common device hotplug code
>> introduced previously. This reduces the driver down to a trivial
>> definition and registration of a struct acpi_scan_handler object.
>>
>> Signed-off-by: Rafael J. Wysocki <[email protected]>
>> Acked-by: Toshi Kani <[email protected]>
>> Tested-by: Toshi Kani <[email protected]>
>> ---
>> drivers/acpi/container.c | 146
>> ++++-------------------------------------------
>> 1 file changed, 10 insertions(+), 136 deletions(-)
>>
>>
>> I'm now investigating this problem. If you have any idea about why this
>> happens, please let me know.
>
> With the above change, container devices use the common notify handler,
> which logs the warning message in question when it receives device check
> twice on a same device. Before the change, the container-specific
> notify handler did not log this message in the same case (but considered
> it as an eject request).
>
> So, I suspect that you are getting device check twice regardless of the
> kernel change. Can you check KERN_DEBUG messages to see if that is the
> case? The notify handler logs all events with KERN_DEBUG.

Follow your suggestion, we confirm that it really received ACPI_NOTIFY_
DEVICE_CHECK event*twice*, but the original ACPI container driver only
received once, does the common device hotplug code introduce another device
check? any idea?

Container uses common device hotplug code:
[ 142.937724] IPv6: ADDRCONF(NETDEV_CHANGE): eth8: link becomes ready
[ 674.975575] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
[ 674.991604] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
[ 675.613990] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
[ 675.684970] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
[ 675.780957] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
[ 675.874806] ACPI _OSC control for PCIe not granted, disabling ASPM
[ 675.949005] pci_bus 0000:fd: Allocating resources
[ 675.960145] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
[ 676.031176] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
[ 676.127129] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
[ 676.220943] ACPI _OSC control for PCIe not granted, disabling ASPM
[ 676.295019] pci_bus 0000:fc: Allocating resources

Original ACPI container driver:
[ 1526.122933] Container driver received ACPI_NOTIFY_DEVICE_CHECK event <<<<
[ 1526.800646] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
[ 1526.871682] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
[ 1526.967878] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
[ 1527.061891] ACPI _OSC control for PCIe not granted, disabling ASPM
[ 1527.136036] pci_bus 0000:fd: Allocating resources
[ 1527.150747] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
[ 1527.221821] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
[ 1527.317738] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
[ 1527.411795] ACPI _OSC control for PCIe not granted, disabling ASPM
[ 1527.485917] pci_bus 0000:fc: Allocating resources


Thanks,
Gu

>
> Thanks,
> -Toshi
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>

2013-09-25 14:25:08

by Rafael J. Wysocki

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

On Wednesday, September 25, 2013 06:31:09 PM Gu Zheng wrote:
> Hi Toshi,
>
> On 09/12/2013 11:11 PM, Toshi Kani wrote:
>
> > On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
> >> Hi Rafael, Toshi,
> >>
> >> When we hot-add an ACPI0004 device, we got the following warning:
> >>
> >> acpi ACPI0004:01: Attempt to re-insert
> >>
> >> The ACPI0004 device is a System Board in Fujitsu server, which has two
> >> numa nodes (processors and memory).
> >>
> >> It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
> >> acpi_hotplug_notify_cb().
> >>
> >>
> >> According to bisect, this happens after the following commit:
> >>
> >> From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
> >> From: "Rafael J. Wysocki" <[email protected]>
> >> Date: Sun, 3 Mar 2013 23:05:55 +0100
> >> Subject: [PATCH 1/1] ACPI / container: Use common hotplug code
> >>
> >> Switch the ACPI container driver to using common device hotplug code
> >> introduced previously. This reduces the driver down to a trivial
> >> definition and registration of a struct acpi_scan_handler object.
> >>
> >> Signed-off-by: Rafael J. Wysocki <[email protected]>
> >> Acked-by: Toshi Kani <[email protected]>
> >> Tested-by: Toshi Kani <[email protected]>
> >> ---
> >> drivers/acpi/container.c | 146
> >> ++++-------------------------------------------
> >> 1 file changed, 10 insertions(+), 136 deletions(-)
> >>
> >>
> >> I'm now investigating this problem. If you have any idea about why this
> >> happens, please let me know.
> >
> > With the above change, container devices use the common notify handler,
> > which logs the warning message in question when it receives device check
> > twice on a same device. Before the change, the container-specific
> > notify handler did not log this message in the same case (but considered
> > it as an eject request).
> >
> > So, I suspect that you are getting device check twice regardless of the
> > kernel change. Can you check KERN_DEBUG messages to see if that is the
> > case? The notify handler logs all events with KERN_DEBUG.
>
> Follow your suggestion, we confirm that it really received ACPI_NOTIFY_
> DEVICE_CHECK event*twice*, but the original ACPI container driver only
> received once, does the common device hotplug code introduce another device
> check? any idea?

Well, we couldn't possibly make the BIOS generate the event twice unless
there's an _OST response missing somewhere or similar.

In any case the second event should be harmless.

> Container uses common device hotplug code:
> [ 142.937724] IPv6: ADDRCONF(NETDEV_CHANGE): eth8: link becomes ready
> [ 674.975575] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
> [ 674.991604] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<

Where exactly did you put that printk()?

> [ 675.613990] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
> [ 675.684970] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 675.780957] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 675.874806] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 675.949005] pci_bus 0000:fd: Allocating resources
> [ 675.960145] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
> [ 676.031176] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 676.127129] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 676.220943] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 676.295019] pci_bus 0000:fc: Allocating resources
>
> Original ACPI container driver:
> [ 1526.122933] Container driver received ACPI_NOTIFY_DEVICE_CHECK event <<<<

And that?

> [ 1526.800646] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
> [ 1526.871682] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 1526.967878] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 1527.061891] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 1527.136036] pci_bus 0000:fd: Allocating resources
> [ 1527.150747] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
> [ 1527.221821] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 1527.317738] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 1527.411795] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 1527.485917] pci_bus 0000:fc: Allocating resources

Thanks,
Rafael

2013-09-25 22:26:50

by Toshi Kani

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

On Wed, 2013-09-25 at 10:31 +0000, Gu Zheng wrote:
> Hi Toshi,
>
> On 09/12/2013 11:11 PM, Toshi Kani wrote:
>
> > On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
> >> Hi Rafael, Toshi,
> >>
> >> When we hot-add an ACPI0004 device, we got the following warning:
> >>
> >> acpi ACPI0004:01: Attempt to re-insert
> >>
> >> The ACPI0004 device is a System Board in Fujitsu server, which has two
> >> numa nodes (processors and memory).
> >>
> >> It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
> >> acpi_hotplug_notify_cb().
> >>
> >>
> >> According to bisect, this happens after the following commit:
> >>
> >> From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
> >> From: "Rafael J. Wysocki" <[email protected]>
> >> Date: Sun, 3 Mar 2013 23:05:55 +0100
> >> Subject: [PATCH 1/1] ACPI / container: Use common hotplug code
> >>
> >> Switch the ACPI container driver to using common device hotplug code
> >> introduced previously. This reduces the driver down to a trivial
> >> definition and registration of a struct acpi_scan_handler object.
> >>
> >> Signed-off-by: Rafael J. Wysocki <[email protected]>
> >> Acked-by: Toshi Kani <[email protected]>
> >> Tested-by: Toshi Kani <[email protected]>
> >> ---
> >> drivers/acpi/container.c | 146
> >> ++++-------------------------------------------
> >> 1 file changed, 10 insertions(+), 136 deletions(-)
> >>
> >>
> >> I'm now investigating this problem. If you have any idea about why this
> >> happens, please let me know.
> >
> > With the above change, container devices use the common notify handler,
> > which logs the warning message in question when it receives device check
> > twice on a same device. Before the change, the container-specific
> > notify handler did not log this message in the same case (but considered
> > it as an eject request).
> >
> > So, I suspect that you are getting device check twice regardless of the
> > kernel change. Can you check KERN_DEBUG messages to see if that is the
> > case? The notify handler logs all events with KERN_DEBUG.
>
> Follow your suggestion, we confirm that it really received ACPI_NOTIFY_
> DEVICE_CHECK event*twice*, but the original ACPI container driver only
> received once, does the common device hotplug code introduce another device
> check? any idea?
>
> Container uses common device hotplug code:
> [ 142.937724] IPv6: ADDRCONF(NETDEV_CHANGE): eth8: link becomes ready
> [ 674.975575] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<

acpi_hotplug_notify_cb() calls acpi_os_hotplug_execute() to schedule to
run acpi_scan_device_check() asynchronously and returns immediately.
This leads acpi_ev_asynch_enable_gpe() to run next, which clears this
GPE (if level triggered) and re-enable GPE.

> [ 674.991604] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<

It appears that re-enabling GPE caused this GPE to show up again as a
spurious interrupt.

> [ 675.613990] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
> [ 675.684970] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 675.780957] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 675.874806] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 675.949005] pci_bus 0000:fd: Allocating resources
> [ 675.960145] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
> [ 676.031176] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 676.127129] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 676.220943] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 676.295019] pci_bus 0000:fc: Allocating resources
>
> Original ACPI container driver:
> [ 1526.122933] Container driver received ACPI_NOTIFY_DEVICE_CHECK event <<<<

In the original code, container_notify_cb() proceeds the device check
handling and then calls _OST on the same thread. It then re-enable GPE.
This ordering seems to avoid the spurious interrupt on your platform.

> [ 1526.800646] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
> [ 1526.871682] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 1526.967878] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 1527.061891] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 1527.136036] pci_bus 0000:fd: Allocating resources
> [ 1527.150747] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
> [ 1527.221821] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
> [ 1527.317738] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
> [ 1527.411795] ACPI _OSC control for PCIe not granted, disabling ASPM
> [ 1527.485917] pci_bus 0000:fc: Allocating resources

The GPE handler code in ACPICA is the same. So, the issue could be due
to either;
- The firmware expects _OST before re-enabling GPE, or
- The timing of re-enabling GPE was too soon on your platform.

Can you check with your firmware team to see if this might be the case?

Thanks,
-Toshi

2013-09-26 02:38:26

by Gu Zheng

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

Hi Rafael,

On 09/25/2013 10:36 PM, Rafael J. Wysocki wrote:

> On Wednesday, September 25, 2013 06:31:09 PM Gu Zheng wrote:
>> Hi Toshi,
>>
>> On 09/12/2013 11:11 PM, Toshi Kani wrote:
>>
>>> On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
>>>> Hi Rafael, Toshi,
>>>>
>>>> When we hot-add an ACPI0004 device, we got the following warning:
>>>>
>>>> acpi ACPI0004:01: Attempt to re-insert
<...>
>>>>
>>>>
>>>> I'm now investigating this problem. If you have any idea about why this
>>>> happens, please let me know.
>>>
>>> With the above change, container devices use the common notify handler,
>>> which logs the warning message in question when it receives device check
>>> twice on a same device. Before the change, the container-specific
>>> notify handler did not log this message in the same case (but considered
>>> it as an eject request).
>>>
>>> So, I suspect that you are getting device check twice regardless of the
>>> kernel change. Can you check KERN_DEBUG messages to see if that is the
>>> case? The notify handler logs all events with KERN_DEBUG.
>>
>> Follow your suggestion, we confirm that it really received ACPI_NOTIFY_
>> DEVICE_CHECK event*twice*, but the original ACPI container driver only
>> received once, does the common device hotplug code introduce another device
>> check? any idea?
>
> Well, we couldn't possibly make the BIOS generate the event twice unless
> there's an _OST response missing somewhere or similar.
>
> In any case the second event should be harmless.

Yes, though it's harmless, but this message is not very friendly.

>
>> Container uses common device hotplug code:
>> [ 142.937724] IPv6: ADDRCONF(NETDEV_CHANGE): eth8: link becomes ready
>> [ 674.975575] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
>> [ 674.991604] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
>
> Where exactly did you put that printk()?

It's the acpi_handle_debug in acpi_hotplug_notify_cb():
410 case ACPI_NOTIFY_DEVICE_CHECK:
411 acpi_handle_debug(handle, "ACPI_NOTIFY_DEVICE_CHECK event\n");
412 callback = acpi_scan_device_check;
413 break;

>
>> [ 675.613990] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
>> [ 675.684970] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 675.780957] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 675.874806] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 675.949005] pci_bus 0000:fd: Allocating resources
>> [ 675.960145] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
>> [ 676.031176] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 676.127129] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 676.220943] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 676.295019] pci_bus 0000:fc: Allocating resources
>>
>> Original ACPI container driver:
>> [ 1526.122933] Container driver received ACPI_NOTIFY_DEVICE_CHECK event <<<<
>
> And that?

It seems that the original ACPI container driver can avoid the second event.

The debug printk is added in original container_notify_cb():
96 case ACPI_NOTIFY_DEVICE_CHECK:
97 printk("Container driver received %s event\n",
98 (type == ACPI_NOTIFY_BUS_CHECK) ?
99 "ACPI_NOTIFY_BUS_CHECK" : "ACPI_NOTIFY_DEVICE_CHECK");
100
101 present = is_device_present(handle);
102 status = acpi_bus_get_device(handle, &device);
103 if (device)
104 printk("=======attemp to reinsert!\n");
105 if (!present) {

Best regards,
Gu

>
>> [ 1526.800646] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
>> [ 1526.871682] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 1526.967878] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 1527.061891] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 1527.136036] pci_bus 0000:fd: Allocating resources
>> [ 1527.150747] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
>> [ 1527.221821] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 1527.317738] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 1527.411795] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 1527.485917] pci_bus 0000:fc: Allocating resources
>
> Thanks,
> Rafael
>
>

2013-09-26 02:38:38

by Gu Zheng

[permalink] [raw]
Subject: Re: [Bug report] Warning when hot-add an ACPI0004 device.

Hi Toshi,

On 09/26/2013 06:24 AM, Toshi Kani wrote:

> On Wed, 2013-09-25 at 10:31 +0000, Gu Zheng wrote:
>> Hi Toshi,
>>
>> On 09/12/2013 11:11 PM, Toshi Kani wrote:
>>
>>> On Thu, 2013-09-12 at 13:00 +0800, Tang Chen wrote:
>>>> Hi Rafael, Toshi,
>>>>
>>>> When we hot-add an ACPI0004 device, we got the following warning:
>>>>
>>>> acpi ACPI0004:01: Attempt to re-insert
>>>>
>>>> The ACPI0004 device is a System Board in Fujitsu server, which has two
>>>> numa nodes (processors and memory).
>>>>
>>>> It seems that we reserved the ACPI_NOTIFY_DEVICE_CHECK event twice in
>>>> acpi_hotplug_notify_cb().
>>>>
>>>>
>>>> According to bisect, this happens after the following commit:
>>>>
>>>> From 68a67f6c78b80525d9b3c6672e7782de95e56a83 Mon Sep 17 00:00:00 2001
>>>> From: "Rafael J. Wysocki" <[email protected]>
>>>> Date: Sun, 3 Mar 2013 23:05:55 +0100
>>>> Subject: [PATCH 1/1] ACPI / container: Use common hotplug code
>>>>
>>>> Switch the ACPI container driver to using common device hotplug code
>>>> introduced previously. This reduces the driver down to a trivial
>>>> definition and registration of a struct acpi_scan_handler object.
>>>>
>>>> Signed-off-by: Rafael J. Wysocki <[email protected]>
>>>> Acked-by: Toshi Kani <[email protected]>
>>>> Tested-by: Toshi Kani <[email protected]>
>>>> ---
>>>> drivers/acpi/container.c | 146
>>>> ++++-------------------------------------------
>>>> 1 file changed, 10 insertions(+), 136 deletions(-)
>>>>
>>>>
>>>> I'm now investigating this problem. If you have any idea about why this
>>>> happens, please let me know.
>>>
>>> With the above change, container devices use the common notify handler,
>>> which logs the warning message in question when it receives device check
>>> twice on a same device. Before the change, the container-specific
>>> notify handler did not log this message in the same case (but considered
>>> it as an eject request).
>>>
>>> So, I suspect that you are getting device check twice regardless of the
>>> kernel change. Can you check KERN_DEBUG messages to see if that is the
>>> case? The notify handler logs all events with KERN_DEBUG.
>>
>> Follow your suggestion, we confirm that it really received ACPI_NOTIFY_
>> DEVICE_CHECK event*twice*, but the original ACPI container driver only
>> received once, does the common device hotplug code introduce another device
>> check? any idea?
>>
>> Container uses common device hotplug code:
>> [ 142.937724] IPv6: ADDRCONF(NETDEV_CHANGE): eth8: link becomes ready
>> [ 674.975575] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
>
> acpi_hotplug_notify_cb() calls acpi_os_hotplug_execute() to schedule to
> run acpi_scan_device_check() asynchronously and returns immediately.
> This leads acpi_ev_asynch_enable_gpe() to run next, which clears this
> GPE (if level triggered) and re-enable GPE.

Thanks for your explanation, it's really the routine you mentioned above.

>
>> [ 674.991604] ACPI: \_SB_.LSB1: ACPI_NOTIFY_DEVICE_CHECK event <<<<
>
> It appears that re-enabling GPE caused this GPE to show up again as a
> spurious interrupt.

Yes, it is.

>
>> [ 675.613990] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
>> [ 675.684970] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 675.780957] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 675.874806] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 675.949005] pci_bus 0000:fd: Allocating resources
>> [ 675.960145] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
>> [ 676.031176] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 676.127129] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 676.220943] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 676.295019] pci_bus 0000:fc: Allocating resources
>>
>> Original ACPI container driver:
>> [ 1526.122933] Container driver received ACPI_NOTIFY_DEVICE_CHECK event <<<<
>
> In the original code, container_notify_cb() proceeds the device check
> handling and then calls _OST on the same thread. It then re-enable GPE.

According to our debug, the whole routine was executed on the same thread.

> This ordering seems to avoid the spurious interrupt on your platform.

It seems that, but it is very strange.

>
>> [ 1526.800646] ACPI: PCI Root Bridge [UNC2] (domain 0000 [bus fd])
>> [ 1526.871682] acpi PNP0A03:01: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 1526.967878] acpi PNP0A03:01: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 1527.061891] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 1527.136036] pci_bus 0000:fd: Allocating resources
>> [ 1527.150747] ACPI: PCI Root Bridge [UNC3] (domain 0000 [bus fc])
>> [ 1527.221821] acpi PNP0A03:02: ACPI _OSC support notification failed, disabling PCIe ASPM
>> [ 1527.317738] acpi PNP0A03:02: Unable to request _OSC control (_OSC support mask: 0x08)
>> [ 1527.411795] ACPI _OSC control for PCIe not granted, disabling ASPM
>> [ 1527.485917] pci_bus 0000:fc: Allocating resources
>
> The GPE handler code in ACPICA is the same. So, the issue could be due
> to either;
> - The firmware expects _OST before re-enabling GPE, or
> - The timing of re-enabling GPE was too soon on your platform.

Thanks for your directions.

>
> Can you check with your firmware team to see if this might be the case?

I'll confirm this.

Best regards,
Gu

>
> Thanks,
> -Toshi
>
>