Re: INFO: possible circular locking dependency - kacpid acpi_os_wait_events_complete

[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.

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
>