Bug 1155804 - possible circular locking dependency detected cpuidle_pause_and_lock, cpu_hotplug_begin
Summary: possible circular locking dependency detected cpuidle_pause_and_lock, cpu_hot...
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-10-22 21:09 UTC by Zbigniew Jędrzejewski-Szmek
Modified: 2014-11-10 14:14 UTC (History)
7 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-11-10 14:14:24 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
boot log (139.66 KB, text/x-vhdl)
2014-10-22 21:09 UTC, Zbigniew Jędrzejewski-Szmek
no flags Details

Description Zbigniew Jędrzejewski-Szmek 2014-10-22 21:09:29 UTC
Created attachment 949580 [details]
boot log

Description of problem:
I was trying to reproduce nirik's suspend/resume hang. I get this instead, which seems unrelated, apart from the fact that it happens during suspend:

Oct 22 16:24:42 fedora22 kernel: ======================================================
Oct 22 16:24:42 fedora22 kernel: [ INFO: possible circular locking dependency detected ]
Oct 22 16:24:42 fedora22 kernel: 3.18.0-0.rc1.git0.1.fc22.x86_64+debug #1 Not tainted
Oct 22 16:24:42 fedora22 kernel: -------------------------------------------------------
Oct 22 16:24:42 fedora22 kernel: systemd-sleep/1268 is trying to acquire lock:
Oct 22 16:24:42 fedora22 kernel:  (cpuidle_lock){+.+...}, at: [<ffffffff816ad537>] cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel: 
                                 but task is already holding lock:
Oct 22 16:24:42 fedora22 kernel:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810abf18>] cpu_hotplug_begin+0x58/0x90
Oct 22 16:24:42 fedora22 kernel: 
                                 which lock already depends on the new lock.
Oct 22 16:24:42 fedora22 kernel: 
                                 the existing dependency chain (in reverse order) is:
Oct 22 16:24:42 fedora22 kernel: 
                                 -> #1 (cpu_hotplug.lock#2){+.+.+.}:
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8110d5b1>] lock_acquire+0xd1/0x2b0
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81860c8e>] mutex_lock_nested+0x7e/0x440
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff816ad717>] cpuidle_pause+0x17/0x30
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8156dc2f>] dpm_suspend_noirq+0x5f/0x620
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8111583e>] suspend_devices_and_enter+0x27e/0xc90
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81116757>] pm_suspend+0x507/0x580
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81114470>] state_store+0x80/0x100
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8141fc4f>] kobj_attr_store+0xf/0x20
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff813046d9>] sysfs_kf_write+0x49/0x60
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81303a19>] kernfs_fop_write+0xf9/0x180
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81274f2a>] vfs_write+0xba/0x200
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81275a7c>] SyS_write+0x5c/0xd0
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff818663a9>] system_call_fastpath+0x12/0x17
Oct 22 16:24:42 fedora22 kernel: 
                                 -> #0 (cpuidle_lock){+.+...}:
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8110cb77>] __lock_acquire+0x1c67/0x1df0
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8110d5b1>] lock_acquire+0xd1/0x2b0
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81860c8e>] mutex_lock_nested+0x7e/0x440
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff816ad537>] cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff814ef86f>] acpi_processor_hotplug+0x4f/0x8d
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff814ed069>] acpi_cpu_soft_notify+0xc1/0x10b
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff810d51c2>] notifier_call_chain+0x62/0x100
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff810d526e>] __raw_notifier_call_chain+0xe/0x10
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff810abde3>] cpu_notify+0x23/0x50
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff810ac108>] _cpu_up+0x178/0x190
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81850c07>] enable_nonboot_cpus+0xe7/0x490
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8111599d>] suspend_devices_and_enter+0x3dd/0xc90
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81116757>] pm_suspend+0x507/0x580
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81114470>] state_store+0x80/0x100
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff8141fc4f>] kobj_attr_store+0xf/0x20
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff813046d9>] sysfs_kf_write+0x49/0x60
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81303a19>] kernfs_fop_write+0xf9/0x180
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81274f2a>] vfs_write+0xba/0x200
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff81275a7c>] SyS_write+0x5c/0xd0
Oct 22 16:24:42 fedora22 kernel:        [<ffffffff818663a9>] system_call_fastpath+0x12/0x17
Oct 22 16:24:42 fedora22 kernel: 
                                 other info that might help us debug this:
Oct 22 16:24:42 fedora22 kernel:  Possible unsafe locking scenario:
Oct 22 16:24:42 fedora22 kernel:        CPU0                    CPU1
Oct 22 16:24:42 fedora22 kernel:        ----                    ----
Oct 22 16:24:42 fedora22 kernel:   lock(cpu_hotplug.lock#2);
Oct 22 16:24:42 fedora22 kernel:                                lock(cpuidle_lock);
Oct 22 16:24:42 fedora22 kernel:                                lock(cpu_hotplug.lock#2);
Oct 22 16:24:42 fedora22 kernel:   lock(cpuidle_lock);
Oct 22 16:24:42 fedora22 kernel: 
                                  *** DEADLOCK ***
Oct 22 16:24:42 fedora22 kernel: 8 locks held by systemd-sleep/1268:
Oct 22 16:24:42 fedora22 kernel:  #0:  (sb_writers#3){.+.+.+}, at: [<ffffffff81275013>] vfs_write+0x1a3/0x200
Oct 22 16:24:42 fedora22 kernel:  #1:  (&of->mutex){+.+.+.}, at: [<ffffffff813039e7>] kernfs_fop_write+0xc7/0x180
Oct 22 16:24:42 fedora22 kernel:  #2:  (s_active#107){.+.+.+}, at: [<ffffffff813039f0>] kernfs_fop_write+0xd0/0x180
Oct 22 16:24:42 fedora22 kernel:  #3:  (pm_mutex){+.+.+.}, at: [<ffffffff8111640c>] pm_suspend+0x1bc/0x580
Oct 22 16:24:42 fedora22 kernel:  #4:  (acpi_scan_lock){+.+.+.}, at: [<ffffffff814ab14a>] acpi_scan_lock_acquire+0x17/0x19
Oct 22 16:24:42 fedora22 kernel:  #5:  (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff81850b44>] enable_nonboot_cpus+0x24/0x490
Oct 22 16:24:42 fedora22 kernel:  #6:  (cpu_hotplug.lock){++++++}, at: [<ffffffff810abec5>] cpu_hotplug_begin+0x5/0x90
Oct 22 16:24:42 fedora22 kernel:  #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810abf18>] cpu_hotplug_begin+0x58/0x90
Oct 22 16:24:42 fedora22 kernel: 
                                 stack backtrace:
Oct 22 16:24:42 fedora22 kernel: CPU: 0 PID: 1268 Comm: systemd-sleep Not tainted 3.18.0-0.rc1.git0.1.fc22.x86_64+debug #1
Oct 22 16:24:42 fedora22 kernel: Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Oct 22 16:24:42 fedora22 kernel:  0000000000000000 00000000f1153b98 ffff8800780ab998 ffffffff8185be1d
Oct 22 16:24:42 fedora22 kernel:  0000000000000000 ffffffff82a9d600 ffff8800780ab9e8 ffffffff8185939c
Oct 22 16:24:42 fedora22 kernel:  00000000001d6a40 ffff8800780aba48 ffff8800785bccc0 ffff8800785bd798
Oct 22 16:24:42 fedora22 kernel: Call Trace:
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8185be1d>] dump_stack+0x4e/0x68
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8185939c>] print_circular_bug+0x203/0x214
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8110cb77>] __lock_acquire+0x1c67/0x1df0
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8106ac07>] ? kvm_clock_read+0x27/0x40
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8110d5b1>] lock_acquire+0xd1/0x2b0
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff816ad537>] ? cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81860c8e>] mutex_lock_nested+0x7e/0x440
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff816ad537>] ? cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff814a6f21>] ? acpi_os_wait_semaphore+0xa4/0x17f
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff816ad537>] ? cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff814e923f>] ? acpi_ut_release_mutex+0xb2/0xba
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff816ad537>] cpuidle_pause_and_lock+0x17/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff814ef86f>] acpi_processor_hotplug+0x4f/0x8d
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff814ed069>] acpi_cpu_soft_notify+0xc1/0x10b
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff810d51c2>] notifier_call_chain+0x62/0x100
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff810d526e>] __raw_notifier_call_chain+0xe/0x10
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff810abde3>] cpu_notify+0x23/0x50
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff810ac108>] _cpu_up+0x178/0x190
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81850c07>] enable_nonboot_cpus+0xe7/0x490
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff811155b2>] ? arch_suspend_enable_irqs+0x12/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8111599d>] suspend_devices_and_enter+0x3dd/0xc90
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81116757>] pm_suspend+0x507/0x580
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81114470>] state_store+0x80/0x100
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff8141fc4f>] kobj_attr_store+0xf/0x20
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff813046d9>] sysfs_kf_write+0x49/0x60
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81303a19>] kernfs_fop_write+0xf9/0x180
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81274f2a>] vfs_write+0xba/0x200
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff81275a7c>] SyS_write+0x5c/0xd0
Oct 22 16:24:42 fedora22 kernel:  [<ffffffff818663a9>] system_call_fastpath+0x12/0x17


Version-Release number of selected component (if applicable):


How reproducible:
100% (during first suspend after boot)

Steps to Reproduce:
1. systemctl suspend

Actual results:
suspend works, just that the warning is printed

Comment 1 Josh Boyer 2014-10-28 18:26:39 UTC
Please try the 3.18.0-0.rc2.git1.1 kernel that is current building.  There was an upstream RCU issue that was causing hangs for a number of people.

Comment 2 Zbigniew Jędrzejewski-Szmek 2014-11-10 14:14:24 UTC
After updates I'm not seeing this anymore.


Note You need to log in before you can comment on or make changes to this bug.