Re: pm-hibernate : possible circular locking dependency detected

From: Gautham R Shenoy
Date: Sun Apr 05 2009 - 20:56:18 EST

Next message: Jeff Chua: "[PATCH] fix mm/filemap.c:841: error: redefinition of'__kcrctab_add_to_page_cache_lru'"
Previous message: David Rientjes: "[patch] slub: default min_partial to at least highest cpus pernode"
In reply to: Ingo Molnar: "Re: pm-hibernate : possible circular locking dependency detected"
Next in thread: Rafael J. Wysocki: "Re: pm-hibernate : possible circular locking dependency detected"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Sun, Apr 05, 2009 at 03:44:54PM +0200, Ingo Molnar wrote:
>
> * Rafael J. Wysocki <rjw@xxxxxxx> wrote:
>
> > On Sunday 05 April 2009, Ming Lei wrote:
> > > kernel version : one simple usb-serial patch against commit
> > > 6bb597507f9839b13498781e481f5458aea33620.
> > >
> > > Thanks.
> >
> > Hmm, CPU hotplug again, it seems.
> >
> > I'm not sure who's the maintainer at the moment. Andrew, is that
> > Gautham?
>
> CPU hotplug tends to land on the scheduler people's desk normally.
>
> But i'm not sure that's the real thing here - key appears to be this
> work_on_cpu() worklet by the cpufreq code:

Actually, there are two dependency chains here which can lead to a deadlock.
The one we're seeing here is the longer of the two.

If the relevant locks are numbered as follows:
[1]: cpu_policy_rwsem
[2]: work_on_cpu
[3]: cpu_hotplug.lock
[4]: dpm_list_mtx

The individual callpaths are:

1) do_dbs_timer()[1] --> dbs_check_cpu() --> __cpufreq_driver_getavg()
|
work_on_cpu()[2] <-- get_measured_perf() <--|

2) pci_device_probe() --> .. --> pci_call_probe() [3] --> work_on_cpu()[2]
|
[4] device_pm_add() <-- ..<-- local_pci_probe() <--|

3) hibernate() --> hibernatioin_snapshot() --> create_image()
|
disable_nonboot_cpus() <-- [4] device_pm_lock() <--|
|
|--> _cpu_down() [3] --> cpufreq_cpu_callback() [1]

The two chains which can deadlock are

a) [1] --> [2] --> [4] --> [3] --> [1] (The one in this log)
and
b) [3] --> [2] --> [4] --> [3]

Ingo,
do_dbs_timer() function of the ondemand governor is run from a per-cpu
workqueue. Hence it is already running on the cpu whose perf counters
we're interested in.

Does it make sense to introduce a get_this_measured_perf() API
for users who are already running on the relevant CPU ?
And have get_measured_perf(cpu) for other users (currently there are
none) ?

Thus, do_dbs_timer() can avoid calling work_on_cpu() thereby preventing
deadlock a) from occuring.

Rafael,
Sorry, I am not well versed with the hibernation code. But does the
following make sense:

create_image()
{
device_pm_lock();
device_power_down(PMSG_FREEZE);
platform_pre_snapshot(platform_mode);

device_pm_unlock();
disable_nonboot_cpus()
device_pm_lock();
.
.
.
.
}

>
> > > [ 2276.033134] -> #1 (work_on_cpu){+.+.+.}:
> > > [ 2276.033138] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.033141] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033145] [<ffffffff80250885>] flush_work+0x60/0xeb
> > > [ 2276.033148] [<ffffffff80250c49>] work_on_cpu+0x73/0x84
> > > [ 2276.033151] [<ffffffffa02b4399>] get_cur_val+0xb6/0xe3 [acpi_cpufreq]
> > > [ 2276.033157] [<ffffffffa02b443a>]
> > > get_cur_freq_on_cpu+0x74/0xc5 [acpi_cpufreq]
> > > [ 2276.033161] [<ffffffffa02b4b69>]
> > > acpi_cpufreq_cpu_init+0x381/0x4c4 [acpi_cpufreq]
> > > [ 2276.033166] [<ffffffff803db697>] cpufreq_add_dev+0x1bb/0x676
>
> Connecting things the wrong way around. Have not looked deeply
> though - Peter, Rusty, what's your take? (below is the message
> again)
>
> Ingo
>
> > > [ 2276.031486] PM: Saving platform NVS memory
> > > [ 2276.032410] Disabling non-boot CPUs ...
> > > [ 2276.032879]
> > > [ 2276.032880] =======================================================
> > > [ 2276.032882] [ INFO: possible circular locking dependency detected ]
> > > [ 2276.032885] 2.6.29-08003-g8b58977 #84
> > > [ 2276.032886] -------------------------------------------------------
> > > [ 2276.032888] pm-hibernate/5061 is trying to acquire lock:
> > > [ 2276.032891] (&per_cpu(cpu_policy_rwsem, cpu)){+++++.}, at:
> > > [<ffffffff803db46e>] lock_policy_rwsem_write+0x48/0x79
> > > [ 2276.032900]
> > > [ 2276.032900] but task is already holding lock:
> > > [ 2276.032902] (&cpu_hotplug.lock){+.+.+.}, at: [<ffffffff80240d38>]
> > > cpu_hotplug_begin+0x22/0x50
> > > [ 2276.032908]
> > > [ 2276.032909] which lock already depends on the new lock.
> > > [ 2276.032910]
> > > [ 2276.032911]
> > > [ 2276.032912] the existing dependency chain (in reverse order) is:
> > > [ 2276.032913]
> > > [ 2276.032914] -> #6 (&cpu_hotplug.lock){+.+.+.}:
> > > [ 2276.032918] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.032922] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.032926] [<ffffffff804763db>] mutex_lock_nested+0x6a/0x362
> > > [ 2276.032930] [<ffffffff80240d38>] cpu_hotplug_begin+0x22/0x50
> > > [ 2276.032933] [<ffffffff804728b0>] _cpu_up+0x58/0x12f
> > > [ 2276.032937] [<ffffffff804729ea>] cpu_up+0x63/0x78
> > > [ 2276.032940] [<ffffffff806585cb>] kernel_init+0xbd/0x189
> > > [ 2276.032944] [<ffffffff8020c1fa>] child_rip+0xa/0x20
> > > [ 2276.032948] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.032960]
> > > [ 2276.032961] -> #5 (cpu_add_remove_lock){+.+.+.}:
> > > [ 2276.032964] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.032968] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.032971] [<ffffffff804763db>] mutex_lock_nested+0x6a/0x362
> > > [ 2276.032974] [<ffffffff80240d02>] cpu_maps_update_begin+0x12/0x14
> > > [ 2276.032978] [<ffffffff80250526>] __create_workqueue_key+0xdc/0x1a2
> > > [ 2276.032982] [<ffffffff80276eaf>] stop_machine_create+0x3a/0x9b
> > > [ 2276.032987] [<ffffffff8026d959>] load_module+0x58/0x18c8
> > > [ 2276.032990] [<ffffffff8026f320>] sys_init_module+0x57/0x1cd
> > > [ 2276.032993] [<ffffffff8020b0c2>] system_call_fastpath+0x16/0x1b
> > > [ 2276.032998] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033001]
> > > [ 2276.033001] -> #4 (setup_lock){+.+.+.}:
> > > [ 2276.033005] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.033008] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033012] [<ffffffff804763db>] mutex_lock_nested+0x6a/0x362
> > > [ 2276.033015] [<ffffffff80276e87>] stop_machine_create+0x12/0x9b
> > > [ 2276.033018] [<ffffffff80240d7c>] disable_nonboot_cpus+0x16/0x120
> > > [ 2276.033022] [<ffffffff80271994>] hibernation_snapshot+0x99/0x1ac
> > > [ 2276.033025] [<ffffffff80271b52>] hibernate+0xab/0x1cf
> > > [ 2276.033028] [<ffffffff802705f0>] state_store+0x59/0xd7
> > > [ 2276.033032] [<ffffffff8034788f>] kobj_attr_store+0x17/0x19
> > > [ 2276.033036] [<ffffffff8030f7d0>] sysfs_write_file+0xe4/0x119
> > > [ 2276.033040] [<ffffffff802c0d14>] vfs_write+0xae/0x137
> > > [ 2276.033044] [<ffffffff802c0e61>] sys_write+0x47/0x6e
> > > [ 2276.033047] [<ffffffff8020b0c2>] system_call_fastpath+0x16/0x1b
> > > [ 2276.033050] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033053]
> > > [ 2276.033054] -> #3 (dpm_list_mtx){+.+.+.}:
> > > [ 2276.033057] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.033061] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033065] [<ffffffff804763db>] mutex_lock_nested+0x6a/0x362
> > > [ 2276.033068] [<ffffffff803c4339>] device_pm_add+0x46/0xed
> > > [ 2276.033073] [<ffffffff803bdeee>] device_add+0x488/0x61a
> > > [ 2276.033077] [<ffffffff803be099>] device_register+0x19/0x1d
> > > [ 2276.033080] [<ffffffff8036031a>] pcie_port_device_register+0x450/0x4b6
> > > [ 2276.033085] [<ffffffff80469999>] pcie_portdrv_probe+0x69/0x82
> > > [ 2276.033089] [<ffffffff8035bf77>] local_pci_probe+0x12/0x16
> > > [ 2276.033093] [<ffffffff8024fdf8>] do_work_for_cpu+0x13/0x1b
> > > [ 2276.033097] [<ffffffff80250038>] worker_thread+0x1b2/0x2c9
> > > [ 2276.033100] [<ffffffff80253d40>] kthread+0x49/0x76
> > > [ 2276.033104] [<ffffffff8020c1fa>] child_rip+0xa/0x20
> > > [ 2276.033107] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033111]
> > > [ 2276.033111] -> #2 (&wfc.work){+.+.+.}:
> > > [ 2276.033114] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.033118] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033122] [<ffffffff80250032>] worker_thread+0x1ac/0x2c9
> > > [ 2276.033125] [<ffffffff80253d40>] kthread+0x49/0x76
> > > [ 2276.033128] [<ffffffff8020c1fa>] child_rip+0xa/0x20
> > > [ 2276.033131] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033134]
> > > [ 2276.033134] -> #1 (work_on_cpu){+.+.+.}:
> > > [ 2276.033138] [<ffffffff80265579>] __lock_acquire+0x1402/0x178c
> > > [ 2276.033141] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033145] [<ffffffff80250885>] flush_work+0x60/0xeb
> > > [ 2276.033148] [<ffffffff80250c49>] work_on_cpu+0x73/0x84
> > > [ 2276.033151] [<ffffffffa02b4399>] get_cur_val+0xb6/0xe3 [acpi_cpufreq]
> > > [ 2276.033157] [<ffffffffa02b443a>]
> > > get_cur_freq_on_cpu+0x74/0xc5 [acpi_cpufreq]
> > > [ 2276.033161] [<ffffffffa02b4b69>]
> > > acpi_cpufreq_cpu_init+0x381/0x4c4 [acpi_cpufreq]
> > > [ 2276.033166] [<ffffffff803db697>] cpufreq_add_dev+0x1bb/0x676
> > > [ 2276.033169] [<ffffffff803bea90>] sysdev_driver_register+0xc6/0x120
> > > [ 2276.033173] [<ffffffff803da5c1>] cpufreq_register_driver+0xbc/0x1ae
> > > [ 2276.033177] [<ffffffffa00c60c5>] 0xffffffffa00c60c5
> > > [ 2276.033180] [<ffffffff80209076>] do_one_initcall+0x70/0x185
> > > [ 2276.033183] [<ffffffff8026f374>] sys_init_module+0xab/0x1cd
> > > [ 2276.033187] [<ffffffff8020b0c2>] system_call_fastpath+0x16/0x1b
> > > [ 2276.033190] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033197]
> > > [ 2276.033197] -> #0 (&per_cpu(cpu_policy_rwsem, cpu)){+++++.}:
> > > [ 2276.033201] [<ffffffff80265296>] __lock_acquire+0x111f/0x178c
> > > [ 2276.033204] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033208] [<ffffffff80476d6c>] down_write+0x43/0x77
> > > [ 2276.033211] [<ffffffff803db46e>] lock_policy_rwsem_write+0x48/0x79
> > > [ 2276.033215] [<ffffffff80474678>] cpufreq_cpu_callback+0x52/0x7a
> > > [ 2276.033218] [<ffffffff80257ebb>] notifier_call_chain+0x33/0x5b
> > > [ 2276.033222] [<ffffffff80257f42>] __raw_notifier_call_chain+0x9/0xb
> > > [ 2276.033226] [<ffffffff80465097>] _cpu_down+0x86/0x298
> > > [ 2276.033229] [<ffffffff80240dde>] disable_nonboot_cpus+0x78/0x120
> > > [ 2276.033233] [<ffffffff80271994>] hibernation_snapshot+0x99/0x1ac
> > > [ 2276.033236] [<ffffffff80271b52>] hibernate+0xab/0x1cf
> > > [ 2276.033239] [<ffffffff802705f0>] state_store+0x59/0xd7
> > > [ 2276.033242] [<ffffffff8034788f>] kobj_attr_store+0x17/0x19
> > > [ 2276.033246] [<ffffffff8030f7d0>] sysfs_write_file+0xe4/0x119
> > > [ 2276.033249] [<ffffffff802c0d14>] vfs_write+0xae/0x137
> > > [ 2276.033252] [<ffffffff802c0e61>] sys_write+0x47/0x6e
> > > [ 2276.033255] [<ffffffff8020b0c2>] system_call_fastpath+0x16/0x1b
> > > [ 2276.033259] [<ffffffffffffffff>] 0xffffffffffffffff
> > > [ 2276.033262]
> > > [ 2276.033262] other info that might help us debug this:
> > > [ 2276.033263]
> > > [ 2276.033265] 5 locks held by pm-hibernate/5061:
> > > [ 2276.033267] #0: (&buffer->mutex){+.+.+.}, at:
> > > [<ffffffff8030f724>] sysfs_write_file+0x38/0x119
> > > [ 2276.033273] #1: (pm_mutex){+.+.+.}, at: [<ffffffff80271abe>]
> > > hibernate+0x17/0x1cf
> > > [ 2276.033278] #2: (dpm_list_mtx){+.+.+.}, at: [<ffffffff803c35c5>]
> > > device_pm_lock+0x12/0x14
> > > [ 2276.033284] #3: (cpu_add_remove_lock){+.+.+.}, at:
> > > [<ffffffff80240d99>] disable_nonboot_cpus+0x33/0x120
> > > [ 2276.033289] #4: (&cpu_hotplug.lock){+.+.+.}, at:
> > > [<ffffffff80240d38>] cpu_hotplug_begin+0x22/0x50
> > > [ 2276.033294]
> > > [ 2276.033295] stack backtrace:
> > > [ 2276.033297] Pid: 5061, comm: pm-hibernate Not tainted
> > > 2.6.29-08003-g8b58977 #84
> > > [ 2276.033300] Call Trace:
> > > [ 2276.033304] [<ffffffff80263cbf>] print_circular_bug_tail+0xc5/0xd0
> > > [ 2276.033307] [<ffffffff80265296>] __lock_acquire+0x111f/0x178c
> > > [ 2276.033312] [<ffffffff802382b0>] ? sub_preempt_count+0xdc/0xf1
> > > [ 2276.033315] [<ffffffff80263470>] ? trace_hardirqs_on+0xd/0xf
> > > [ 2276.033319] [<ffffffff80265996>] lock_acquire+0x93/0xbf
> > > [ 2276.033322] [<ffffffff803db46e>] ? lock_policy_rwsem_write+0x48/0x79
> > > [ 2276.033326] [<ffffffff80476d6c>] down_write+0x43/0x77
> > > [ 2276.033329] [<ffffffff803db46e>] ? lock_policy_rwsem_write+0x48/0x79
> > > [ 2276.033333] [<ffffffff803db46e>] lock_policy_rwsem_write+0x48/0x79
> > > [ 2276.033337] [<ffffffff80474678>] cpufreq_cpu_callback+0x52/0x7a
> > > [ 2276.033340] [<ffffffff80257ebb>] notifier_call_chain+0x33/0x5b
> > > [ 2276.033344] [<ffffffff80257f42>] __raw_notifier_call_chain+0x9/0xb
> > > [ 2276.033347] [<ffffffff80465097>] _cpu_down+0x86/0x298
> > > [ 2276.033350] [<ffffffff80240dde>] disable_nonboot_cpus+0x78/0x120
> > > [ 2276.033350] [<ffffffff80271994>] hibernation_snapshot+0x99/0x1ac
> > > [ 2276.033350] [<ffffffff80271b52>] hibernate+0xab/0x1cf
> > > [ 2276.033350] [<ffffffff802705f0>] state_store+0x59/0xd7
> > > [ 2276.033350] [<ffffffff8034788f>] kobj_attr_store+0x17/0x19
> > > [ 2276.033350] [<ffffffff8030f7d0>] sysfs_write_file+0xe4/0x119
> > > [ 2276.033350] [<ffffffff802c0d14>] vfs_write+0xae/0x137
> > > [ 2276.033350] [<ffffffff802c0e61>] sys_write+0x47/0x6e
> > > [ 2276.033350] [<ffffffff8020b0c2>] system_call_fastpath+0x16/0x1b
> > > [ 2276.034478] Broke affinity for irq 21
> > > [ 2276.034478] Broke affinity for irq 22
> > > [ 2276.034478] Broke affinity for irq 29
> > > [ 2276.035812] CPU 1 is now offline
> > > [ 2276.035814] lockdep: fixing up alternatives.
> > > [ 2276.035816] SMP alternatives: switching to UP code
> > > [ 2276.158329] CPU0 attaching NULL sched-domain.
> > > [ 2276.158334] CPU1 attaching NULL sched-domain.
> > > [ 2276.158361] CPU0 attaching NULL sched-domain.
> > > [ 2276.158841] CPU1 is down
> > > [ 2276.158867] Checking wake-up interrupts
> > > [ 2276.158883] Suspending System Devices
> > > [ 2276.158885] Suspending type 'oprofile':
> > > [ 2276.158886] oprofile0
> > > [ 2276.158888] Suspending type 'edac':
> > > [ 2276.158889] Suspending type 'irqrouter':
> > > [ 2276.158891] irqrouter0
> > > [ 2276.158892] Suspending type 'clocksource':
> > > [ 2276.158894] clocksource0
> > > [ 2276.158895] Suspending type 'timekeeping':
> > > [ 2276.158897] timekeeping0
> > > [ 2276.158929] Extended CMOS year: 2000
> > > [ 2276.158937] Suspending type 'ioapic':
> > > [ 2276.158938] ioapic0
> > > [ 2276.159007] Suspending type 'lapic':
> > > [ 2276.159007] lapic0
> > > [ 2276.159007] Suspending type 'machinecheck':
> > > [ 2276.159007] machinecheck0
> > > [ 2276.159007] Suspending type 'i8237':
> > > [ 2276.159007] i82370
> > > [ 2276.159007] Suspending type 'i8259':
> > > [ 2276.159007] i82590
> > > [ 2276.159007] Suspending type 'node':
> > > [ 2276.159007] node0
> > > [ 2276.159007] Suspending type 'cpu':
> > > [ 2276.159007] cpu0
> > > [ 2276.159007] cpu1
> > > [ 2276.159007] PM: Creating hibernation image:
> > > [ 2276.159007] PM: Need to copy 112986 pages
> > > [ 2276.159007] PM: Restoring platform NVS memory
> > > [ 2276.159007] Resuming System Devices
> > > [ 2276.159007] Resuming type 'cpu':
> > > [ 2276.159007] cpu0
> > > [ 2276.159007] cpu1
> > > [ 2276.159007] Resuming type 'node':
> > > [ 2276.159007] node0
> > > [ 2276.159007] Resuming type 'i8259':
> > > [ 2276.159007] i82590
> > > [ 2276.159007] Resuming type 'i8237':
> > > [ 2276.159007] i82370
> > > [ 2276.159007] Resuming type 'machinecheck':
> > > [ 2276.159007] machinecheck0
> > > [ 2276.159007] CPU0: Thermal LVT vector (0xfa) already installed
> > > [ 2276.159007] Resuming type 'lapic':
> > > [ 2276.159007] lapic0
> > > [ 2276.159007] Resuming type 'ioapic':
> > > [ 2276.159007] ioapic0
> > > [ 2276.159007] Resuming type 'timekeeping':
> > > [ 2276.159007] timekeeping0
> > > [ 2276.159007] Extended CMOS year: 2000
> > > [ 2276.159007] Resuming type 'clocksource':
> > > [ 2276.159007] clocksource0
> > > [ 2276.159007] Resuming type 'irqrouter':
> > > [ 2276.159007] irqrouter0
> > > [ 2276.159007] Resuming type 'edac':
> > > [ 2276.159007] Resuming type 'oprofile':
> > > [ 2276.159007] oprofile0

--
Thanks and Regards
gautham
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Jeff Chua: "[PATCH] fix mm/filemap.c:841: error: redefinition of'__kcrctab_add_to_page_cache_lru'"
Previous message: David Rientjes: "[patch] slub: default min_partial to at least highest cpus pernode"
In reply to: Ingo Molnar: "Re: pm-hibernate : possible circular locking dependency detected"
Next in thread: Rafael J. Wysocki: "Re: pm-hibernate : possible circular locking dependency detected"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]