INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[Zdenek Kabelac]

Hi

Now with 2.6.31-rc7 (3edf2fb9d80a46d6c32ba12547a42419845b4b76)
 I'm getting this  INFO trace - also I've noticed complete reset during resume
which could be eventually related to this ?

My machine - T61, 4GB, C2D
I suspect that some resent  thinkpad-acpi changes.

ACPI: Preparing to enter system sleep state S3
Disabling non-boot CPUs ...
kvm: disabling virtualization on CPU1
CPU 1 is now offline
lockdep: fixing up alternatives.
SMP alternatives: switching to UP code
CPU0 attaching NULL sched-domain.
CPU1 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
CPU1 is down
Extended CMOS year: 2000
x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
Back to C!
CPU0: Thermal monitoring handled by SMI
Extended CMOS year: 2000
Enabling non-boot CPUs ...
lockdep: fixing up alternatives.
SMP alternatives: switching to SMP code
Booting processor 1 APIC 0x1 ip 0x6000
Initializing CPU#1
Calibrating delay using timer specific routine.. 4390.86 BogoMIPS (lpj=7314990)
CPU: L1 I cache: 32K, L1 D cache: 32K
CPU: L2 cache: 4096K
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 1
mce: CPU supports 6 MCE banks
CPU1: Thermal monitoring enabled (TM2)
x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106
CPU1: Intel(R) Core(TM)2 Duo CPU     T7500  @ 2.20GHz stepping 0a
kvm: enabling virtualization on CPU1
CPU0 attaching NULL sched-domain.
Switched to high resolution mode on CPU 1
CPU0 attaching sched-domain:
 domain 0: span 0-1 level CPU
  groups: 0 1
CPU1 attaching sched-domain:
 domain 0: span 0-1 level CPU
  groups: 1 0
CPU1 is up
ACPI: Waking up from system sleep state S3

=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.31-rc7-00015-ge740538 #18
-------------------------------------------------------
kacpi_hotplug/114 is trying to acquire lock:
 (kacpid){+.+.+.}, at: [<ffffffff81064df0>] flush_workqueue+0x0/0xc0

but task is already holding lock:
 (&dpc->work){+.+.+.}, at: [<ffffffff81065183>] worker_thread+0x193/0x3f0

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (&dpc->work){+.+.+.}:
       [<ffffffff8107eeac>] __lock_acquire+0xc5c/0x1090
       [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
       [<ffffffff810651ce>] worker_thread+0x1de/0x3f0
       [<ffffffff810690e6>] kthread+0xa6/0xb0
       [<ffffffff8100d2da>] child_rip+0xa/0x20
       [<ffffffffffffffff>] 0xffffffffffffffff

-> #0 (kacpid){+.+.+.}:
       [<ffffffff8107ef7f>] __lock_acquire+0xd2f/0x1090
       [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
       [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
       [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
       [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
       [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0
       [<ffffffff810690e6>] kthread+0xa6/0xb0
       [<ffffffff8100d2da>] child_rip+0xa/0x20
       [<ffffffffffffffff>] 0xffffffffffffffff

other info that might help us debug this:

2 locks held by kacpi_hotplug/114:
 #0:  (kacpi_hotplug){+.+...}, at: [<ffffffff81065183>]
worker_thread+0x193/0x3f0
 #1:  (&dpc->work){+.+.+.}, at: [<ffffffff81065183>] worker_thread+0x193/0x3f0

stack backtrace:
Pid: 114, comm: kacpi_hotplug Not tainted 2.6.31-rc7-00015-ge740538 #18
Call Trace:
 [<ffffffff8107cf0d>] print_circular_bug_tail+0x9d/0xe0
 [<ffffffff8107ef7f>] __lock_acquire+0xd2f/0x1090
 [<ffffffff8107b5ff>] ? save_trace+0x3f/0xb0
 [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
 [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
 [<ffffffff81261532>] ? acpi_os_execute_hp_deferred+0x0/0x43
 [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
 [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
 [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
 [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
 [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0
 [<ffffffff81065183>] ? worker_thread+0x193/0x3f0
 [<ffffffff8107b2fe>] ? put_lock_stats+0xe/0x30
 [<ffffffff81069540>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff81064ff0>] ? worker_thread+0x0/0x3f0
 [<ffffffff810690e6>] kthread+0xa6/0xb0
 [<ffffffff8100d2da>] child_rip+0xa/0x20
 [<ffffffff8100cc40>] ? restore_args+0x0/0x30
 [<ffffffff81069040>] ? kthread+0x0/0xb0
 [<ffffffff8100d2d0>] ? child_rip+0x0/0x20
ACPI: \_SB_.GDCK - docking
acpi IBM0079:00: parent device:00 should not be sleeping
pci 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007,
writing 0x900403)
pci 0000:00:02.1: restoring config space at offset 0x1 (was 0x900000,
writing 0x900007)
uhci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was
0x2800005, writing 0x2800001)
uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
uhci_hcd 0000:00:1a.1: restoring config space at offset 0x1 (was
0x2800005, writing 0x2800001)
ehci_hcd 0000:00:1a.7: restoring config space at offset 0x1 (was
0x2900106, writing 0x2900102)
ehci_hcd 0000:00:1a.7: PME# disabled
HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was
0x100106, writing 0x100102)


Zdenek

Re: INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[Bjorn Helgaas]

On Tuesday 25 August 2009 02:10:58 am Zdenek Kabelac wrote:
> Now with 2.6.31-rc7 (3edf2fb9d80a46d6c32ba12547a42419845b4b76)
>  I'm getting this  INFO trace - also I've noticed complete reset during resume
> which could be eventually related to this ?

What's the most recent kernel where this did not occur?  Is this
a regression since 2.6.30?

> My machine - T61, 4GB, C2D
> I suspect that some resent  thinkpad-acpi changes.

Do you have any evidence that points to thinkpad_acpi?  I looked
at the recent changes there, and I don't see anything obviously
related to kacpid or deferred work.

I made a recent change to the kacpid workqueue (74b58208082).
If it's convenient to revert that change and test, it'd be
good to rule that out.

Thanks for your report!

Bjorn

> ACPI: Preparing to enter system sleep state S3
> Disabling non-boot CPUs ...
> kvm: disabling virtualization on CPU1
> CPU 1 is now offline
> lockdep: fixing up alternatives.
> SMP alternatives: switching to UP code
> CPU0 attaching NULL sched-domain.
> CPU1 attaching NULL sched-domain.
> CPU0 attaching NULL sched-domain.
> CPU1 is down
> Extended CMOS year: 2000
> x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
> Back to C!
> CPU0: Thermal monitoring handled by SMI
> Extended CMOS year: 2000
> Enabling non-boot CPUs ...
> lockdep: fixing up alternatives.
> SMP alternatives: switching to SMP code
> Booting processor 1 APIC 0x1 ip 0x6000
> Initializing CPU#1
> Calibrating delay using timer specific routine.. 4390.86 BogoMIPS (lpj=7314990)
> CPU: L1 I cache: 32K, L1 D cache: 32K
> CPU: L2 cache: 4096K
> CPU: Physical Processor ID: 0
> CPU: Processor Core ID: 1
> mce: CPU supports 6 MCE banks
> CPU1: Thermal monitoring enabled (TM2)
> x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106
> CPU1: Intel(R) Core(TM)2 Duo CPU     T7500  @ 2.20GHz stepping 0a
> kvm: enabling virtualization on CPU1
> CPU0 attaching NULL sched-domain.
> Switched to high resolution mode on CPU 1
> CPU0 attaching sched-domain:
>  domain 0: span 0-1 level CPU
>   groups: 0 1
> CPU1 attaching sched-domain:
>  domain 0: span 0-1 level CPU
>   groups: 1 0
> CPU1 is up
> ACPI: Waking up from system sleep state S3
> 
> =======================================================
> [ INFO: possible circular locking dependency detected ]
> 2.6.31-rc7-00015-ge740538 #18
> -------------------------------------------------------
> kacpi_hotplug/114 is trying to acquire lock:
>  (kacpid){+.+.+.}, at: [<ffffffff81064df0>] flush_workqueue+0x0/0xc0
> 
> but task is already holding lock:
>  (&dpc->work){+.+.+.}, at: [<ffffffff81065183>] worker_thread+0x193/0x3f0
> 
> which lock already depends on the new lock.
> 
> 
> the existing dependency chain (in reverse order) is:
> 
> -> #1 (&dpc->work){+.+.+.}:
>        [<ffffffff8107eeac>] __lock_acquire+0xc5c/0x1090
>        [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
>        [<ffffffff810651ce>] worker_thread+0x1de/0x3f0
>        [<ffffffff810690e6>] kthread+0xa6/0xb0
>        [<ffffffff8100d2da>] child_rip+0xa/0x20
>        [<ffffffffffffffff>] 0xffffffffffffffff
> 
> -> #0 (kacpid){+.+.+.}:
>        [<ffffffff8107ef7f>] __lock_acquire+0xd2f/0x1090
>        [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
>        [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
>        [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
>        [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
>        [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0
>        [<ffffffff810690e6>] kthread+0xa6/0xb0
>        [<ffffffff8100d2da>] child_rip+0xa/0x20
>        [<ffffffffffffffff>] 0xffffffffffffffff
> 
> other info that might help us debug this:
> 
> 2 locks held by kacpi_hotplug/114:
>  #0:  (kacpi_hotplug){+.+...}, at: [<ffffffff81065183>]
> worker_thread+0x193/0x3f0
>  #1:  (&dpc->work){+.+.+.}, at: [<ffffffff81065183>] worker_thread+0x193/0x3f0
> 
> stack backtrace:
> Pid: 114, comm: kacpi_hotplug Not tainted 2.6.31-rc7-00015-ge740538 #18
> Call Trace:
>  [<ffffffff8107cf0d>] print_circular_bug_tail+0x9d/0xe0
>  [<ffffffff8107ef7f>] __lock_acquire+0xd2f/0x1090
>  [<ffffffff8107b5ff>] ? save_trace+0x3f/0xb0
>  [<ffffffff8107f37a>] lock_acquire+0x9a/0x180
>  [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
>  [<ffffffff81261532>] ? acpi_os_execute_hp_deferred+0x0/0x43
>  [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
>  [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
>  [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
>  [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
>  [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0
>  [<ffffffff81065183>] ? worker_thread+0x193/0x3f0
>  [<ffffffff8107b2fe>] ? put_lock_stats+0xe/0x30
>  [<ffffffff81069540>] ? autoremove_wake_function+0x0/0x40
>  [<ffffffff81064ff0>] ? worker_thread+0x0/0x3f0
>  [<ffffffff810690e6>] kthread+0xa6/0xb0
>  [<ffffffff8100d2da>] child_rip+0xa/0x20
>  [<ffffffff8100cc40>] ? restore_args+0x0/0x30
>  [<ffffffff81069040>] ? kthread+0x0/0xb0
>  [<ffffffff8100d2d0>] ? child_rip+0x0/0x20
> ACPI: \_SB_.GDCK - docking
> acpi IBM0079:00: parent device:00 should not be sleeping
> pci 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007,
> writing 0x900403)
> pci 0000:00:02.1: restoring config space at offset 0x1 (was 0x900000,
> writing 0x900007)
> uhci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was
> 0x2800005, writing 0x2800001)
> uhci_hcd 0000:00:1a.1: power state changed by ACPI to D0
> uhci_hcd 0000:00:1a.1: restoring config space at offset 0x1 (was
> 0x2800005, writing 0x2800001)
> ehci_hcd 0000:00:1a.7: restoring config space at offset 0x1 (was
> 0x2900106, writing 0x2900102)
> ehci_hcd 0000:00:1a.7: PME# disabled
> HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was
> 0x100106, writing 0x100102)
> 
> 
> Zdenek
> 

Re: INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[Zdenek Kabelac]

2009/8/25 Bjorn Helgaas <bjorn.helgaas@hp.com>:
> On Tuesday 25 August 2009 02:10:58 am Zdenek Kabelac wrote:
>> Now with 2.6.31-rc7 (3edf2fb9d80a46d6c32ba12547a42419845b4b76)
>>  I'm getting this  INFO trace - also I've noticed complete reset during resume
>> which could be eventually related to this ?
>
> What's the most recent kernel where this did not occur?  Is this
> a regression since 2.6.30?
>
>> My machine - T61, 4GB, C2D
>> I suspect that some resent  thinkpad-acpi changes.
>
> Do you have any evidence that points to thinkpad_acpi?  I looked
> at the recent changes there, and I don't see anything obviously
> related to kacpid or deferred work.
>

Well I've never seen this INFO trace before - also I'm not sure I
could reliable retest it - might be coincidence of suspend out of port
replicator and resume while being attached on it - however I do this
relatively often and I start to see this after I' started to use -rc7
kernel.

My guess is purely based on the fact that commit touching functions
from INFO trace was recently merged to main tree.

If there will be some time I could try to make few tests for suspend
resume - but I hope the trace would be enough for analysis.

Zdenek

Re: INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[Zdenek Kabelac]

2009/8/25 Bjorn Helgaas <bjorn.helgaas@hp.com>:
> On Tuesday 25 August 2009 02:33:30 pm you wrote:
>> 2009/8/25 Bjorn Helgaas <bjorn.helgaas@hp.com>:
>> > On Tuesday 25 August 2009 02:10:58 am Zdenek Kabelac wrote:
>> >> Now with 2.6.31-rc7 (3edf2fb9d80a46d6c32ba12547a42419845b4b76)
>> >>  I'm getting this  INFO trace - also I've noticed complete reset during resume
>> >> which could be eventually related to this
>> > Do you have any evidence that points to thinkpad_acpi?  I looked
>> > at the recent changes there, and I don't see anything obviously
>> > related to kacpid or deferred work.
>> >
>>
>> Well I've never seen this INFO trace before - also I'm not sure I
>> could reliable retest it - might be coincidence of suspend out of port
>> replicator and resume while being attached on it - however I do this
>> relatively often and I start to see this after I' started to use -rc7
>> kernel.
>>
>> My guess is purely based on the fact that commit touching functions
>> from INFO trace was recently merged to main tree.
>>
>> If there will be some time I could try to make few tests for suspend
>> resume - but I hope the trace would be enough for analysis.
>

Well definitelly I do not have a reliable test case to
deterministically trigger this INFO trace, but I think from the trace
it looks like  the acpi_os_wait_events_complete calls flush_workqueue
which again calls acpi_os_execute_hp_deferred which again tries to
invoke flush_workqueue - so is that correct ?

(__acpi_os_execute looks somewhat cryptic in selection what would be called)

This is the stack traceback cut from my first post:

 [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
 [<ffffffff81261532>] ? acpi_os_execute_hp_deferred+0x0/0x43
 [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
 [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
 [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
 [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
 [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0

So it looks like this issue is releated to commit:
c02256be79a1a3557332ac51e653d574a2a7d2b5

Hopefully the author would be able to fix this ?

Zdenek

Re: INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[Zdenek Kabelac]

2009/8/26 Zdenek Kabelac <zdenek.kabelac@gmail.com>:
> 2009/8/25 Bjorn Helgaas <bjorn.helgaas@hp.com>:
>> On Tuesday 25 August 2009 02:33:30 pm you wrote:
>>> 2009/8/25 Bjorn Helgaas <bjorn.helgaas@hp.com>:
>>> > On Tuesday 25 August 2009 02:10:58 am Zdenek Kabelac wrote:
>>> >> Now with 2.6.31-rc7 (3edf2fb9d80a46d6c32ba12547a42419845b4b76)
>>> >>  I'm getting this  INFO trace - also I've noticed complete reset during resume
>>> >> which could be eventually related to this
>>> > Do you have any evidence that points to thinkpad_acpi?  I looked
>>> > at the recent changes there, and I don't see anything obviously
>>> > related to kacpid or deferred work.
>>> >
>>>
>>> Well I've never seen this INFO trace before - also I'm not sure I
>>> could reliable retest it - might be coincidence of suspend out of port
>>> replicator and resume while being attached on it - however I do this
>>> relatively often and I start to see this after I' started to use -rc7
>>> kernel.
>>>
>>> My guess is purely based on the fact that commit touching functions
>>> from INFO trace was recently merged to main tree.
>>>
>>> If there will be some time I could try to make few tests for suspend
>>> resume - but I hope the trace would be enough for analysis.
>>
>
> Well definitelly I do not have a reliable test case to
> deterministically trigger this INFO trace, but I think from the trace
> it looks like  the acpi_os_wait_events_complete calls flush_workqueue
> which again calls acpi_os_execute_hp_deferred which again tries to
> invoke flush_workqueue - so is that correct ?
>
> (__acpi_os_execute looks somewhat cryptic in selection what would be called)
>
> This is the stack traceback cut from my first post:
>
>  [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
>  [<ffffffff81261532>] ? acpi_os_execute_hp_deferred+0x0/0x43
>  [<ffffffff81064e4f>] flush_workqueue+0x5f/0xc0
>  [<ffffffff81064df0>] ? flush_workqueue+0x0/0xc0
>  [<ffffffff81261524>] acpi_os_wait_events_complete+0x15/0x23
>  [<ffffffff81261561>] acpi_os_execute_hp_deferred+0x2f/0x43
>  [<ffffffff810651d4>] worker_thread+0x1e4/0x3f0
>
> So it looks like this issue is releated to commit:
> c02256be79a1a3557332ac51e653d574a2a7d2b5
>
> Hopefully the author would be able to fix this ?
>

Hi

Any progress with this issue - I'm still getting this INFO trace even
with 2.6.31

Zdenek