Re: 2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock

[Miles Lane]

Sorry.  GMail doesn't support sending unwrapped text, as far as I can
tell.  I will send the log segment to you as an attachment.  Also,
when I sent my .config inline to Andrew recently, it tripped his spam
filter.  I'll attach it as well.

I just managed to reproduce this with a suspend-to-disk (my apologies
for CCing the suspend-to-ram folks).

On Dec 18, 2007 9:08 AM, Johannes Berg <johannes@xxxxxxxxxxxxxxxx> wrote:
>
> On Tue, 2007-12-18 at 09:03 -0500, Miles Lane wrote:
> > I have only seen this happen once, and cannot reproduce it.  I'll keep
> > trying, though.
> >
> > Dec 16 22:10:48 syntropy kernel: [  231.718023]
> > =======================================================
>
> Do you have a version that isn't line-wrapped before I try to unwrap it?
>
> Thanks,
> johannes
>
Dec 18 09:21:38 syntropy kernel: [  111.194326] tifm_7xx1 0000:04:09.2: freeze
Dec 18 09:21:38 syntropy kernel: [  111.194400] ACPI handle has no context!
Dec 18 09:21:38 syntropy kernel: [  111.194434] ACPI: PCI interrupt for device 0000:04:09.2 disabled
Dec 18 09:21:38 syntropy kernel: [  111.194444] ACPI handle has no context!
Dec 18 09:21:38 syntropy kernel: [  111.194582] ohci1394 0000:04:09.1: freeze
Dec 18 09:21:38 syntropy kernel: [  111.194587] ieee1394: hpsb_bus_reset called while bus reset already in progress
Dec 18 09:21:38 syntropy kernel: [  111.194727] ACPI handle has no context!
Dec 18 09:21:38 syntropy kernel: [  111.194895] yenta_cardbus 0000:04:09.0: freeze
Dec 18 09:21:38 syntropy kernel: [  111.195118] iwl3945 0000:03:00.0: freeze
Dec 18 09:21:38 syntropy kernel: [  111.195192] 
Dec 18 09:21:38 syntropy kernel: [  111.195193] =======================================================
Dec 18 09:21:38 syntropy kernel: [  111.195195] [ INFO: possible circular locking dependency detected ]
Dec 18 09:21:38 syntropy kernel: [  111.195198] 2.6.24-rc5-mm1 #7
Dec 18 09:21:38 syntropy kernel: [  111.195200] -------------------------------------------------------
Dec 18 09:21:38 syntropy kernel: [  111.195202] pm-hibernate/5383 is trying to acquire lock:
Dec 18 09:21:38 syntropy kernel: [  111.195204]  (&(&priv->init_alive_start)->work){--..}, at: [__cancel_work_timer+0x8a/0x17f] __cancel_work_timer+0x8a/0x17f
Dec 18 09:21:38 syntropy kernel: [  111.195214] 
Dec 18 09:21:38 syntropy kernel: [  111.195215] but task is already holding lock:
Dec 18 09:21:38 syntropy kernel: [  111.195217]  (&priv->mutex){--..}, at: [<f8d547e7>] iwl3945_pci_suspend+0x1d/0x65 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195234] 
Dec 18 09:21:38 syntropy kernel: [  111.195235] which lock already depends on the new lock.
Dec 18 09:21:38 syntropy kernel: [  111.195236] 
Dec 18 09:21:38 syntropy kernel: [  111.195238] 
Dec 18 09:21:38 syntropy kernel: [  111.195238] the existing dependency chain (in reverse order) is:
Dec 18 09:21:38 syntropy kernel: [  111.195240] 
Dec 18 09:21:38 syntropy kernel: [  111.195241] -> #1 (&priv->mutex){--..}:
Dec 18 09:21:38 syntropy kernel: [  111.195244]        [__lock_acquire+0xa17/0xbf4] __lock_acquire+0xa17/0xbf4
Dec 18 09:21:38 syntropy kernel: [  111.195252]        [mac80211:lock_acquire+0x76/0x1d8] lock_acquire+0x76/0x9d
Dec 18 09:21:38 syntropy kernel: [  111.195257]        [pcmcia:mutex_lock_nested+0xf7/0xd7d] mutex_lock_nested+0xf7/0x294
Dec 18 09:21:38 syntropy kernel: [  111.195265]        [<f8d52ff7>] iwl3945_bg_init_alive_start+0x2d/0x1d7 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195278]        [run_workqueue+0xbb/0x18b] run_workqueue+0xbb/0x18b
Dec 18 09:21:38 syntropy kernel: [  111.195283]        [worker_thread+0xbe/0xcd] worker_thread+0xbe/0xcd
Dec 18 09:21:38 syntropy kernel: [  111.195289]        [kthread+0x3b/0x61] kthread+0x3b/0x61
Dec 18 09:21:38 syntropy kernel: [  111.195295]        [kernel_thread_helper+0x7/0x10] kernel_thread_helper+0x7/0x10
Dec 18 09:21:38 syntropy kernel: [  111.195302]        [<ffffffff>] 0xffffffff
Dec 18 09:21:38 syntropy kernel: [  111.195313] 
Dec 18 09:21:38 syntropy kernel: [  111.195314] -> #0 (&(&priv->init_alive_start)->work){--..}:
Dec 18 09:21:38 syntropy kernel: [  111.195317]        [__lock_acquire+0x93e/0xbf4] __lock_acquire+0x93e/0xbf4
Dec 18 09:21:38 syntropy kernel: [  111.195323]        [mac80211:lock_acquire+0x76/0x1d8] lock_acquire+0x76/0x9d
Dec 18 09:21:38 syntropy kernel: [  111.195329]        [__cancel_work_timer+0xb3/0x17f] __cancel_work_timer+0xb3/0x17f
Dec 18 09:21:38 syntropy kernel: [  111.195335]        [iwl3945:cancel_delayed_work_sync+0xb/0x0d] cancel_delayed_work_sync+0xb/0xd
Dec 18 09:21:38 syntropy kernel: [  111.195341]        [<f8d502cb>] __iwl3945_down+0x51/0x310 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195352]        [<f8d547f7>] iwl3945_pci_suspend+0x2d/0x65 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195364]        [pci_device_suspend+0x1b/0x4b] pci_device_suspend+0x1b/0x4b
Dec 18 09:21:38 syntropy kernel: [  111.195371]        [device_suspend+0x17e/0x259] device_suspend+0x17e/0x259
Dec 18 09:21:38 syntropy kernel: [  111.195378]        [hibernation_snapshot+0x3e/0x173] hibernation_snapshot+0x3e/0x173
Dec 18 09:21:38 syntropy kernel: [  111.195384]        [hibernate+0xba/0x16e] hibernate+0xba/0x16e
Dec 18 09:21:38 syntropy kernel: [  111.195390]        [state_store+0x45/0xac] state_store+0x45/0xac
Dec 18 09:21:38 syntropy kernel: [  111.195395]        [kobj_attr_store+0x1a/0x22] kobj_attr_store+0x1a/0x22
Dec 18 09:21:38 syntropy kernel: [  111.195401]        [sysfs_write_file+0xb8/0xe3] sysfs_write_file+0xb8/0xe3
Dec 18 09:21:38 syntropy kernel: [  111.195408]        [vfs_write+0xa4/0x120] vfs_write+0xa4/0x120
Dec 18 09:21:38 syntropy kernel: [  111.195414]        [sys_write+0x3b/0x60] sys_write+0x3b/0x60
Dec 18 09:21:38 syntropy kernel: [  111.195420]        [sysenter_past_esp+0x6b/0xc1] sysenter_past_esp+0x6b/0xc1
Dec 18 09:21:38 syntropy kernel: [  111.195425]        [<ffffffff>] 0xffffffff
Dec 18 09:21:38 syntropy kernel: [  111.195435] 
Dec 18 09:21:38 syntropy kernel: [  111.195436] other info that might help us debug this:
Dec 18 09:21:38 syntropy kernel: [  111.195437] 
Dec 18 09:21:38 syntropy kernel: [  111.195439] 4 locks held by pm-hibernate/5383:
Dec 18 09:21:38 syntropy kernel: [  111.195441]  #0:  (&buffer->mutex){--..}, at: [sysfs_write_file+0x25/0xe3] sysfs_write_file+0x25/0xe3
Dec 18 09:21:38 syntropy kernel: [  111.195447]  #1:  (pm_mutex){--..}, at: [hibernate+0x10/0x16e] hibernate+0x10/0x16e
Dec 18 09:21:38 syntropy kernel: [  111.195452]  #2:  (dpm_mtx){--..}, at: [device_suspend+0x2b/0x259] device_suspend+0x2b/0x259
Dec 18 09:21:38 syntropy kernel: [  111.195458]  #3:  (&priv->mutex){--..}, at: [<f8d547e7>] iwl3945_pci_suspend+0x1d/0x65 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195470] 
Dec 18 09:21:38 syntropy kernel: [  111.195471] stack backtrace:
Dec 18 09:21:38 syntropy kernel: [  111.195473] Pid: 5383, comm: pm-hibernate Not tainted 2.6.24-rc5-mm1 #7
Dec 18 09:21:38 syntropy kernel: [  111.195476]  [show_trace_log_lvl+0x12/0x25] show_trace_log_lvl+0x12/0x25
Dec 18 09:21:38 syntropy kernel: [  111.195480]  [show_trace+0xd/0x10] show_trace+0xd/0x10
Dec 18 09:21:38 syntropy kernel: [  111.195484]  [sbp2:dump_stack+0x57/0x1734] dump_stack+0x57/0x5f
Dec 18 09:21:38 syntropy kernel: [  111.195487]  [print_circular_bug_tail+0x5b/0x66] print_circular_bug_tail+0x5b/0x66
Dec 18 09:21:38 syntropy kernel: [  111.195491]  [__lock_acquire+0x93e/0xbf4] __lock_acquire+0x93e/0xbf4
Dec 18 09:21:38 syntropy kernel: [  111.195495]  [mac80211:lock_acquire+0x76/0x1d8] lock_acquire+0x76/0x9d
Dec 18 09:21:38 syntropy kernel: [  111.195498]  [__cancel_work_timer+0xb3/0x17f] __cancel_work_timer+0xb3/0x17f
Dec 18 09:21:38 syntropy kernel: [  111.195502]  [iwl3945:cancel_delayed_work_sync+0xb/0x0d] cancel_delayed_work_sync+0xb/0xd
Dec 18 09:21:38 syntropy kernel: [  111.195506]  [<f8d502cb>] __iwl3945_down+0x51/0x310 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195516]  [<f8d547f7>] iwl3945_pci_suspend+0x2d/0x65 [iwl3945]
Dec 18 09:21:38 syntropy kernel: [  111.195525]  [pci_device_suspend+0x1b/0x4b] pci_device_suspend+0x1b/0x4b
Dec 18 09:21:38 syntropy kernel: [  111.195529]  [device_suspend+0x17e/0x259] device_suspend+0x17e/0x259
Dec 18 09:21:38 syntropy kernel: [  111.195533]  [hibernation_snapshot+0x3e/0x173] hibernation_snapshot+0x3e/0x173
Dec 18 09:21:38 syntropy kernel: [  111.195537]  [hibernate+0xba/0x16e] hibernate+0xba/0x16e
Dec 18 09:21:38 syntropy kernel: [  111.195540]  [state_store+0x45/0xac] state_store+0x45/0xac
Dec 18 09:21:38 syntropy kernel: [  111.195543]  [kobj_attr_store+0x1a/0x22] kobj_attr_store+0x1a/0x22
Dec 18 09:21:38 syntropy kernel: [  111.195547]  [sysfs_write_file+0xb8/0xe3] sysfs_write_file+0xb8/0xe3
Dec 18 09:21:38 syntropy kernel: [  111.195550]  [vfs_write+0xa4/0x120] vfs_write+0xa4/0x120
Dec 18 09:21:38 syntropy kernel: [  111.195553]  [sys_write+0x3b/0x60] sys_write+0x3b/0x60
Dec 18 09:21:38 syntropy kernel: [  111.195557]  [sysenter_past_esp+0x6b/0xc1] sysenter_past_esp+0x6b/0xc1
Dec 18 09:21:38 syntropy kernel: [  111.195560]  =======================
Dec 18 09:21:38 syntropy kernel: [  111.306693] sky2 0000:02:00.0: freeze
Dec 18 09:21:38 syntropy kernel: [  111.307000] pci 0000:00:1f.3: freeze
...
Dec 18 09:21:38 syntropy kernel: [  111.444360] agpgart-intel 0000:00:00.0: LATE freeze
Dec 18 09:21:38 syntropy kernel: [  111.444528] PM: Creating hibernation image: 
Dec 18 09:21:38 syntropy kernel: [  111.444531] WARNING: at arch/x86/kernel/smp_32.c:561 native_smp_call_function_mask()
Dec 18 09:21:38 syntropy kernel: [  111.444535] Pid: 5383, comm: pm-hibernate Not tainted 2.6.24-rc5-mm1 #7
Dec 18 09:21:38 syntropy kernel: [  111.444538]  [show_trace_log_lvl+0x12/0x25] show_trace_log_lvl+0x12/0x25
Dec 18 09:21:38 syntropy kernel: [  111.444546]  [show_trace+0xd/0x10] show_trace+0xd/0x10
Dec 18 09:21:38 syntropy kernel: [  111.444550]  [sbp2:dump_stack+0x57/0x1734] dump_stack+0x57/0x5f
Dec 18 09:21:38 syntropy kernel: [  111.444554]  [native_smp_call_function_mask+0x41/0x126] native_smp_call_function_mask+0x41/0x126
Dec 18 09:21:38 syntropy kernel: [  111.444559]  [smp_call_function+0x18/0x1f] smp_call_function+0x18/0x1f
Dec 18 09:21:38 syntropy kernel: [  111.444563]  [on_each_cpu+0x12/0x40] on_each_cpu+0x12/0x40
Dec 18 09:21:38 syntropy kernel: [  111.444568]  [drain_all_pages+0x13/0x16] drain_all_pages+0x13/0x16
Dec 18 09:21:38 syntropy kernel: [  111.444573]  [swsusp_save+0x18/0x46b] swsusp_save+0x18/0x46b
Dec 18 09:21:38 syntropy kernel: [  111.444577]  [swsusp_arch_suspend+0x2a/0x2c] swsusp_arch_suspend+0x2a/0x2c
Dec 18 09:21:38 syntropy kernel: [  111.444583]  [hibernate+0xba/0x16e] hibernate+0xba/0x16e
Dec 18 09:21:38 syntropy kernel: [  111.444586]  [state_store+0x45/0xac] state_store+0x45/0xac
Dec 18 09:21:38 syntropy kernel: [  111.444590]  [kobj_attr_store+0x1a/0x22] kobj_attr_store+0x1a/0x22
Dec 18 09:21:38 syntropy kernel: [  111.444594]  [sysfs_write_file+0xb8/0xe3] sysfs_write_file+0xb8/0xe3
Dec 18 09:21:38 syntropy kernel: [  111.444599]  [vfs_write+0xa4/0x120] vfs_write+0xa4/0x120
Dec 18 09:21:38 syntropy kernel: [  111.444603]  [sys_write+0x3b/0x60] sys_write+0x3b/0x60
Dec 18 09:21:38 syntropy kernel: [  111.444606]  [sysenter_past_esp+0x6b/0xc1] sysenter_past_esp+0x6b/0xc1
Dec 18 09:21:38 syntropy kernel: [  111.444610]  =======================
Dec 18 09:21:38 syntropy kernel: [  111.532605] PM: Need to copy 117627 pages
Dec 18 09:21:38 syntropy kernel: [  111.532609] PM: Normal pages needed: 49097 + 1024 + 40, available pages: 180175
Dec 18 09:21:38 syntropy kernel: [   47.808434] Intel machine check architecture supported.
Dec 18 09:21:38 syntropy kernel: [   47.808441] Intel machine check reporting enabled on CPU#0.
Dec 18 09:21:38 syntropy kernel: [   47.808449] evxfevnt-0079 [00] enable                : System is already in ACPI mode
Dec 18 09:21:38 syntropy kernel: [   47.808809] agpgart-intel 0000:00:00.0: EARLY resume

Attachment: .config
Description: Binary data