Hello,
just in case anybody's interested: While going through old kernel logs
(2.6.31-rc2), I found the warning mentioned in the subject line.
Apparently happened during a failed suspend attempt. Concerning
reproduceability: I've only seen this once so far, and that's nearly a
month ago.
Partial dmesg output is attached. My chip is an Atheros AR2425 (Eee PC
1000HGO).
Kind regards,
Thiemo
--
+-----------------------------------+--------------------------+
| Dipl.-Phys. Thiemo Nagel | |
| Technische Universitaet Muenchen | Room PH1 3276 |
| Physik-Department E18 | |
| James-Franck-Strasse | Phone +49 89 289-12379 |
| D-85747 Garching | Fax +49 89 289-12570 |
+-----------------------------------+--------------------------+
[ 1602.364260] ath5k phy0: noise floor calibration timeout (2452MHz)
[ 1710.758584] wlan0: deauthenticating by local choice (reason=3)
[ 1710.850862] wlan0: deauthenticating by local choice (reason=3)
[ 1710.851705] ------------[ cut here ]------------
[ 1710.851749] WARNING: at drivers/net/wireless/ath/ath5k/base.c:3151
ath5k_bss_info_changed+0x4a/0x144 [ath5k]()
[ 1710.851762] Hardware name: 1000HG
[ 1710.851769] Modules linked in: i915 drm i2c_algo_bit rfcomm l2cap bluetooth
acpi_cpufreq cpufreq_conservative cpufreq_powersave cpufreq_userspace
cpufreq_stats loop snd_hda_codec_realtek option usbserial snd_hda_intel
snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy
snd_seq_oss snd_seq_midi_event snd_seq usb_storage snd_timer snd_seq_device
ath5k psmouse snd mac80211 soundcore intel_agp rng_core ehci_hcd uhci_hcd ath
atl1e snd_page_alloc agpgart evdev rtc_cmos battery rtc_core rtc_lib ac button
processor sha256_generic dm_crypt dm_mod sd_mod thermal fan ata_piix
ata_generic libata
[ 1710.852066] Pid: 3292, comm: wpa_supplicant Not tainted 2.6.31-rc2 #1
[ 1710.852075] Call Trace:
[ 1710.852097] [<c102e2cc>] warn_slowpath_common+0x60/0x90
[ 1710.852114] [<c102e309>] warn_slowpath_null+0xd/0x10
[ 1710.852152] [<f834f025>] ath5k_bss_info_changed+0x4a/0x144 [ath5k]
[ 1710.852186] [<f834efdb>] ? ath5k_bss_info_changed+0x0/0x144 [ath5k]
[ 1710.852225] [<f8101166>] ieee80211_bss_info_change_notify+0x11d/0x132
[mac80211]
[ 1710.852265] [<f81073fc>] ieee80211_set_disassoc+0x1fe/0x238 [mac80211]
[ 1710.852306] [<f81074a2>] ieee80211_sta_deauthenticate+0x2a/0x33 [mac80211]
[ 1710.852349] [<f810c83b>] ieee80211_deauth+0x16/0x19 [mac80211]
[ 1710.852371] [<c1259fd1>] cfg80211_wext_siwmlme+0x81/0xca
[ 1710.852388] [<c124fcea>] ioctl_standard_call+0x1e1/0x297
[ 1710.852407] [<c11efc2b>] ? dev_name_hash+0x16/0x42
[ 1710.852422] [<c124f889>] wext_handle_ioctl+0xe2/0x178
[ 1710.852438] [<c1259f50>] ? cfg80211_wext_siwmlme+0x0/0xca
[ 1710.852456] [<c1095810>] ? might_fault+0x86/0x88
[ 1710.852471] [<c11f405e>] dev_ioctl+0x5cd/0x5ed
[ 1710.852487] [<c11e590c>] ? sys_sendto+0xa4/0xc3
[ 1710.852503] [<c104dd1e>] ? register_lock_class+0x17/0x272
[ 1710.852519] [<c104e849>] ? mark_lock+0x1e/0x1e4
[ 1710.852536] [<c11e44d0>] ? sock_ioctl+0x0/0x205
[ 1710.852551] [<c11e46c1>] sock_ioctl+0x1f1/0x205
[ 1710.852566] [<c11e44d0>] ? sock_ioctl+0x0/0x205
[ 1710.852582] [<c10b892b>] vfs_ioctl+0x22/0x69
[ 1710.852597] [<c10b8eca>] do_vfs_ioctl+0x4b4/0x4f5
[ 1710.852613] [<c11e5943>] ? sys_send+0x18/0x1a
[ 1710.852628] [<c11e606c>] ? sys_socketcall+0xd0/0x183
[ 1710.852644] [<c10b8f4b>] sys_ioctl+0x40/0x5a
[ 1710.852660] [<c1002f04>] sysenter_do_call+0x12/0x32
[ 1710.852672] ---[ end trace 7de697adf5dc87f8 ]---
[ 1712.767479]
[ 1712.767483] =======================================================
[ 1712.767492] [ INFO: possible circular locking dependency detected ]
[ 1712.767500] 2.6.31-rc2 #1
[ 1712.767505] -------------------------------------------------------
[ 1712.767511] 94cpufreq/27461 is trying to acquire lock:
[ 1712.767518] (&(&dbs_info->work)->work){+.+...}, at: [<c103d737>]
__cancel_work_timer+0x8f/0x190
[ 1712.767540]
[ 1712.767542] but task is already holding lock:
[ 1712.767547] (dbs_mutex){+.+.+.}, at: [<c11d82ec>]
cpufreq_governor_dbs+0x1fc/0x280
[ 1712.767564]
[ 1712.767566] which lock already depends on the new lock.
[ 1712.767569]
[ 1712.767574]
[ 1712.767576] the existing dependency chain (in reverse order) is:
[ 1712.767582]
[ 1712.767583] -> #2 (dbs_mutex){+.+.+.}:
[ 1712.767595] [<c104fe30>] __lock_acquire+0x99d/0xb0c
[ 1712.767607] [<c1050047>] lock_acquire+0xa8/0xc5
[ 1712.767617] [<c126a77d>] __mutex_lock_common+0x3e/0x390
[ 1712.767629] [<c126ab58>] mutex_lock_nested+0x29/0x31
[ 1712.767639] [<c11d8164>] cpufreq_governor_dbs+0x74/0x280
[ 1712.767649] [<c11d6241>] __cpufreq_governor+0x66/0x9d
[ 1712.767659] [<c11d63f6>] __cpufreq_set_policy+0x155/0x1c3
[ 1712.767669] [<c11d75cb>] cpufreq_add_dev+0x4f5/0x618
[ 1712.767679] [<c11a9461>] sysdev_driver_register+0x96/0xe5
[ 1712.767690] [<c11d6502>] cpufreq_register_driver+0x9e/0x161
[ 1712.767700] [<f86650b6>] 0xf86650b6
[ 1712.767724] [<c1001137>] do_one_initcall+0x4a/0x111
[ 1712.767735] [<c1058854>] sys_init_module+0xa9/0x1bd
[ 1712.767746] [<c1002f04>] sysenter_do_call+0x12/0x32
[ 1712.767756] [<ffffffff>] 0xffffffff
[ 1712.767771]
[ 1712.767773] -> #1 (&per_cpu(cpu_policy_rwsem, cpu)){+++++.}:
[ 1712.767785] [<c104fe30>] __lock_acquire+0x99d/0xb0c
[ 1712.767795] [<c1050047>] lock_acquire+0xa8/0xc5
[ 1712.767805] [<c126adb0>] down_write+0x2a/0x39
[ 1712.767815] [<c11d7079>] lock_policy_rwsem_write+0x33/0x5b
[ 1712.767826] [<c11d7ee3>] do_dbs_timer+0x4b/0x258
[ 1712.767835] [<c103d04d>] worker_thread+0x1c5/0x2a2
[ 1712.767845] [<c10409fb>] kthread+0x69/0x6e
[ 1712.767855] [<c1003ab7>] kernel_thread_helper+0x7/0x10
[ 1712.767866] [<ffffffff>] 0xffffffff
[ 1712.767901]
[ 1712.767903] -> #0 (&(&dbs_info->work)->work){+.+...}:
[ 1712.767915] [<c104fd42>] __lock_acquire+0x8af/0xb0c
[ 1712.767925] [<c1050047>] lock_acquire+0xa8/0xc5
[ 1712.767935] [<c103d75d>] __cancel_work_timer+0xb5/0x190
[ 1712.767946] [<c103d843>] cancel_delayed_work_sync+0xb/0xd
[ 1712.767956] [<c11d82fb>] cpufreq_governor_dbs+0x20b/0x280
[ 1712.767966] [<c11d6241>] __cpufreq_governor+0x66/0x9d
[ 1712.767976] [<c11d63e0>] __cpufreq_set_policy+0x13f/0x1c3
[ 1712.767986] [<c11d6c43>] store_scaling_governor+0x197/0x1bf
[ 1712.767996] [<c11d7736>] store+0x48/0x61
[ 1712.768005] [<c10f0876>] sysfs_write_file+0xb9/0xe4
[ 1712.768016] [<c10ae700>] vfs_write+0x84/0xdf
[ 1712.768027] [<c10ae7f4>] sys_write+0x3b/0x60
[ 1712.768031] [<c1002f04>] sysenter_do_call+0x12/0x32
[ 1712.768031] [<ffffffff>] 0xffffffff
[ 1712.768031]
[ 1712.768031] other info that might help us debug this:
[ 1712.768031]
[ 1712.768031] 3 locks held by 94cpufreq/27461:
[ 1712.768031] #0: (&buffer->mutex){+.+.+.}, at: [<c10f07e2>]
sysfs_write_file+0x25/0xe4
[ 1712.768031] #1: (&per_cpu(cpu_policy_rwsem, cpu)){+++++.}, at:
[<c11d7079>] lock_policy_rwsem_write+0x33/0x5b
[ 1712.768031] #2: (dbs_mutex){+.+.+.}, at: [<c11d82ec>]
cpufreq_governor_dbs+0x1fc/0x280
[ 1712.768031]
[ 1712.768031] stack backtrace:
[ 1712.768031] Pid: 27461, comm: 94cpufreq Tainted: G W 2.6.31-rc2 #1
[ 1712.768031] Call Trace:
[ 1712.768031] [<c1269522>] ? printk+0xf/0x15
[ 1712.768031] [<c104f1cf>] print_circular_bug_tail+0x5d/0x68
[ 1712.768031] [<c104fd42>] __lock_acquire+0x8af/0xb0c
[ 1712.768031] [<c1050047>] lock_acquire+0xa8/0xc5
[ 1712.768031] [<c103d737>] ? __cancel_work_timer+0x8f/0x190
[ 1712.768031] [<c103d75d>] __cancel_work_timer+0xb5/0x190
[ 1712.768031] [<c103d737>] ? __cancel_work_timer+0x8f/0x190
[ 1712.768031] [<c104ec96>] ? trace_hardirqs_on_caller+0xff/0x120
[ 1712.768031] [<c126aa81>] ? __mutex_lock_common+0x342/0x390
[ 1712.768031] [<c103d843>] cancel_delayed_work_sync+0xb/0xd
[ 1712.768031] [<c11d82fb>] cpufreq_governor_dbs+0x20b/0x280
[ 1712.768031] [<c11d6241>] __cpufreq_governor+0x66/0x9d
[ 1712.768031] [<c11d63e0>] __cpufreq_set_policy+0x13f/0x1c3
[ 1712.768031] [<c11d6c43>] store_scaling_governor+0x197/0x1bf
[ 1712.768031] [<c11d7856>] ? handle_update+0x0/0x28
[ 1712.768031] [<c11d7079>] ? lock_policy_rwsem_write+0x33/0x5b
[ 1712.768031] [<c11d6aac>] ? store_scaling_governor+0x0/0x1bf
[ 1712.768031] [<c11d7736>] store+0x48/0x61
[ 1712.768031] [<c10f0876>] sysfs_write_file+0xb9/0xe4
[ 1712.768031] [<c10f07bd>] ? sysfs_write_file+0x0/0xe4
[ 1712.768031] [<c10ae700>] vfs_write+0x84/0xdf
[ 1712.768031] [<c10ae7f4>] sys_write+0x3b/0x60
[ 1712.768031] [<c1002f04>] sysenter_do_call+0x12/0x32
[ 1713.083615] [drm:i915_get_vblank_counter] *ERROR* trying to get vblank count
for disabled pipe 0
[ 1714.166393] PM: Syncing filesystems ... done.
[ 1714.195518] PM: Preparing system for mem sleep
[ 1714.203407] Freezing user space processes ... (elapsed 0.00 seconds) done.
[ 1714.205400] Freezing remaining freezable tasks ... (elapsed 0.00 seconds)
done.
[ 1714.205841] PM: Entering mem sleep
[ 1714.206036] Suspending console(s) (use no_console_suspend to debug)
[ 1714.206937] pci 0000:00:02.0: PCI INT A disabled
[ 1714.225207] usb 2-6: unlink qh2-0001/f65d3100 start 1 [2/0 us]
[ 1714.225284] option: option_instat_callback: error -2
[ 1714.225871] usb 2-6: usb suspend
[ 1714.236217] hub 2-0:1.0: hub_suspend
[ 1714.236248] usb usb2: bus suspend
[ 1714.236259] ehci_hcd 0000:00:1d.7: suspend root hub
[ 1714.236415] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 1714.487069] sd 0:0:0:0: [sda] Stopping disk
[ 1714.500150] Clocksource tsc unstable (delta = -259306940 ns)
[ 1715.333302] ath5k 0000:01:00.0: PCI INT A disabled
[ 1715.344360] ACPI handle has no context!
[ 1715.344386] ATL1E 0000:03:00.0: PME# disabled
[ 1715.344409] ATL1E 0000:03:00.0: PCI INT A disabled
[ 1715.344440] ACPI handle has no context!
[ 1715.355504] ata_piix 0000:00:1f.2: PCI INT B disabled
[ 1715.366225] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[ 1715.366244] uhci_hcd 0000:00:1d.3: uhci_pci_suspend
[ 1715.366268] uhci_hcd 0000:00:1d.3: PCI INT D disabled
[ 1715.366283] uhci_hcd 0000:00:1d.2: uhci_pci_suspend
[ 1715.366307] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[ 1715.366322] uhci_hcd 0000:00:1d.1: uhci_pci_suspend
[ 1715.366345] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[ 1715.366360] uhci_hcd 0000:00:1d.0: uhci_pci_suspend
[ 1715.366384] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[ 1715.377259] HDA Intel 0000:00:1b.0: PCI INT A disabled
[ 1715.388722] ehci_hcd 0000:00:1d.7: wakeup: 0
[ 1715.388740] ehci_hcd 0000:00:1d.7: PME# disabled
[ 1715.399037] ehci_hcd 0000:00:1d.7: --> PCI D3hot
[ 1715.399085] uhci_hcd 0000:00:1d.3: wakeup: 0
[ 1715.399093] uhci_hcd 0000:00:1d.3: --> PCI D0
[ 1715.399139] uhci_hcd 0000:00:1d.2: wakeup: 0
[ 1715.399147] uhci_hcd 0000:00:1d.2: --> PCI D0
[ 1715.399194] uhci_hcd 0000:00:1d.1: wakeup: 0
[ 1715.399201] uhci_hcd 0000:00:1d.1: --> PCI D0
[ 1715.399247] uhci_hcd 0000:00:1d.0: wakeup: 0
[ 1715.399255] uhci_hcd 0000:00:1d.0: --> PCI D0
[ 1715.399611] ACPI: Preparing to enter system sleep state S3
[ 1715.451351] Disabling non-boot CPUs ...
[ 1715.454248] CPU 1 is now offline
[ 1715.454254] lockdep: fixing up alternatives.
[ 1715.454260] SMP alternatives: switching to UP code
[ 1715.457977] CPU0 attaching NULL sched-domain.
[ 1715.457986] CPU1 attaching NULL sched-domain.
[ 1715.458105] CPU0 attaching NULL sched-domain.
[ 1715.459778] CPU1 is down
[ 1715.459827] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[ 1715.459827] Back to C!
[ 1715.459827] CPU0: Thermal LVT vector (0xfa) already installed
[ 1715.459827] Enabling non-boot CPUs ...
[ 1715.463432] lockdep: fixing up alternatives.
[ 1715.463438] SMP alternatives: switching to SMP code
[ 1715.466370] Booting processor 1 APIC 0x1 ip 0x6000
[ 1715.457546] Initializing CPU#1
[ 1715.457546] Calibrating delay using timer specific routine.. 3200.49
BogoMIPS (lpj=1600247)
[ 1715.457546] CPU: L1 I cache: 32K, L1 D cache: 24K
[ 1715.457546] CPU: L2 cache: 512K
[ 1715.457546] CPU: Physical Processor ID: 0
[ 1715.457546] CPU: Processor Core ID: 0
[ 1715.457546] mce: CPU supports 5 MCE banks
[ 1715.457546] CPU1: Thermal monitoring enabled (TM2)
[ 1715.457546] x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106
[ 1715.538089] CPU1: Intel(R) Atom(TM) CPU N270 @ 1.60GHz stepping 02
[ 1715.538279] Switched to high resolution mode on CPU 1
[ 1715.538334] CPU0 attaching NULL sched-domain.
[ 1715.543084] CPU0 attaching sched-domain:
[ 1715.543094] domain 0: span 0-1 level SIBLING
[ 1715.543102] groups: 0 1
[ 1715.543121] CPU1 attaching sched-domain:
[ 1715.543128] domain 0: span 0-1 level SIBLING
[ 1715.543136] groups: 1 0
[ 1715.557126] CPU1 is up
[ 1715.557135] ACPI: Waking up from system sleep state S3
_______________________________________________
ath5k-devel mailing list
ath5k-devel@lists.ath5k.org
https://lists.ath5k.org/mailman/listinfo/ath5k-devel
