From mboxrd@z Thu Jan 1 00:00:00 1970 Return-path: Received: from mail.candelatech.com ([208.74.158.172]:44042 "EHLO ns3.lanforge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751295Ab3A3F7W (ORCPT ); Wed, 30 Jan 2013 00:59:22 -0500 Message-ID: <5108B6B8.1080603@candelatech.com> (sfid-20130130_065942_646516_0079BEB7) Date: Tue, 29 Jan 2013 21:59:20 -0800 From: Ben Greear MIME-Version: 1.0 To: "linux-wireless@vger.kernel.org" , netdev , Linux Kernel Mailing List Subject: Re: Lockup in barely-patched 3.7.5, maybe wifi/ath9k or i2c related References: <510882F3.4080000@candelatech.com> In-Reply-To: <510882F3.4080000@candelatech.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Sender: linux-wireless-owner@vger.kernel.org List-ID: On 01/29/2013 06:18 PM, Ben Greear wrote: > I've been seeing strange lockups since 3.7.4. Not so easily reproducible > most of the time. Previous lockups looked to be rcu/rtnl based, but the one > below has a bunch of i2c stuff in it. > > Patches applied are a few wifi patches from upstream and one hack to make > ath9k able to over-ride the eeprom regdomain. > > I *think* the decodes are proper, I had to switch back to this patch > set and re-compile.... I saw another lockup, in a similar spot (but no i2c stuff this time). I had also recompiled so that it would not panic on lockup, and by the time I noticed the problem, it seems the lockup resolved itself and the system was stable. So, maybe a false positive on the lockup detector, or maybe it really was locked for a while but then recovered... Thanks, Ben [ 157.985459] sta3: associated [ 274.864154] [sched_delayed] sched: RT throttling activated [ 400.110028] BUG: soft lockup - CPU#1 stuck for 22s! [kworker/1:2:1140] [ 400.110028] Modules linked in: iptable_raw xt_CT nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge veth ip_gre ] [ 400.110028] irq event stamp: 9992689 [ 400.110028] hardirqs last enabled at (9992688): [] __free_pages_ok+0x8f/0xd0 [ 400.110028] hardirqs last disabled at (9992689): [] apic_timer_interrupt+0x32/0x40 [ 400.110028] softirqs last enabled at (4914834): [] __do_softirq+0x10b/0x170 [ 400.110028] softirqs last disabled at (4914915): [] do_softirq+0x9d/0xf0 [ 400.110028] Pid: 1140, comm: kworker/1:2 Tainted: G C 3.7.5+ #39 To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled. [ 400.110028] EIP: 0060:[] EFLAGS: 00000202 CPU: 1 [ 400.110028] EIP is at __free_pages_ok+0x93/0xd0 [ 400.110028] EAX: 00000202 EBX: f6847900 ECX: 00000002 EDX: f5ebba74 [ 400.110028] ESI: 00000003 EDI: 00000202 EBP: f5cc1c34 ESP: f5cc1c24 [ 400.110028] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 400.110028] CR0: 8005003b CR2: 09f2f468 CR3: 00c83000 CR4: 000007e0 [ 400.110028] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 [ 400.110028] DR6: ffff0ff0 DR7: 00000400 [ 400.110028] Process kworker/1:2 (pid: 1140, ti=f5cc0000 task=f5ebb540 task.ti=f75d2000) [ 400.110028] Stack: [ 400.110028] 00000000 f6847900 eff25480 f13cfa00 f5cc1c3c c04ea624 f5cc1c48 c04ef6f0 [ 400.110028] f6847900 f5cc1c5c c04ef7df eff25480 eff25480 f13cfa00 f5cc1c64 c04efd4c [ 400.110028] f5cc1c6c c0854d0f f5cc1c7c c0855a3c eff25480 f09b4000 f5cc1c88 c0855a72 [ 400.110028] Call Trace: [ 400.110028] [] free_compound_page+0x14/0x20 [ 400.110028] [] __put_compound_page+0x10/0x20 [ 400.110028] [] put_compound_page+0x4f/0x190 [ 400.110028] [] put_page+0x2c/0x40 [ 400.110028] [] skb_free_head+0x2f/0x50 [ 400.110028] [] skb_release_data+0x8c/0xb0 [ 400.110028] [] __kfree_skb+0x12/0x90 [ 400.110028] [] kfree_skb+0x17/0x40 [ 400.110028] [] pfifo_fast_enqueue+0x65/0x80 [ 400.110028] [] dev_queue_xmit+0x1e0/0x6e0 [ 400.110028] [] ? ptype_seq_start+0xa0/0xa0 [ 400.110028] [] ieee80211_deliver_skb+0xb1/0x1a0 [mac80211] [ 400.110028] [] ieee80211_rx_handlers+0xd28/0x1940 [mac80211] [ 400.110028] [] ? trace_hardirqs_on_caller+0xa1/0x180 [ 400.110028] [] ? trace_hardirqs_on+0xb/0x10 [ 400.110028] [] ? _raw_spin_unlock_irqrestore+0x3f/0x80 [ 400.110028] [] ieee80211_prepare_and_rx_handle+0x2de/0xaf0 [mac80211] [ 400.110028] [] ieee80211_rx+0x35b/0xa80 [mac80211] [ 400.110028] [] ? ieee80211_rx+0xb1/0xa80 [mac80211] [ 400.110028] [] ath_rx_tasklet+0xde8/0x1340 [ath9k] [ 400.110028] [] ? mark_held_locks+0x64/0xf0 [ 400.110028] [] ath9k_tasklet+0xdf/0x130 [ath9k] [ 400.110028] [] tasklet_action+0xbc/0xd0 [ 400.110028] [] __do_softirq+0xa0/0x170 [ 400.110028] [] ? irq_enter+0x70/0x70 [ 400.110028] [] ? irq_enter+0x70/0x70 [ 400.110028] [ 400.110028] [] ? irq_exit+0xbd/0xe0 [ 400.110028] [] ? do_IRQ+0x46/0xb0 [ 400.110028] [] ? common_interrupt+0x38/0x40 [ 400.110028] [] ? cpufreq_frequency_table_target+0xf2/0x1c0 [ 400.110028] [] ? mark_held_locks+0x64/0xf0 [ 400.110028] [] ? acpi_cpufreq_target+0x6f/0x3b0 [ 400.110028] [] ? smp_call_function_single+0x9c/0x180 [ 400.110028] [] ? mark_held_locks+0x64/0xf0 [ 400.110028] [] ? cpufreq_get_measured_perf+0xd0/0xd0 [ 400.110028] [] ? cpufreq_get_measured_perf+0xba/0xd0 [ 400.110028] [] ? do_drv_read+0x50/0x50 [ 400.110028] [] ? __cpufreq_driver_target+0x48/0xa0 [ 400.110028] [] ? cpufreq_cpu_put+0x17/0x20 [ 400.110028] [] ? __cpufreq_driver_getavg+0x3d/0x70 [ 400.110028] [] ? dbs_check_cpu+0x2d8/0x370 [ 400.110028] [] ? do_dbs_timer+0x35/0xe0 [ 400.110028] [] ? do_dbs_timer+0x87/0xe0 [ 400.110028] [] ? process_one_work+0x1a6/0x3d0 [ 400.110028] [] ? process_one_work+0x139/0x3d0 [ 400.110028] [] ? worker_thread+0x198/0x380 [ 400.110028] [] ? store_ignore_nice_load+0x1c0/0x1c0 [ 400.110028] [] ? worker_thread+0x102/0x380 [ 400.110028] [] ? trace_hardirqs_on+0xb/0x10 [ 400.110028] [] ? kthread+0xac/0xb0 [ 400.110028] [] ? manage_workers+0x2b0/0x2b0 [ 400.110028] [] ? trace_hardirqs_on+0xb/0x10 [ 400.110028] [] ? ret_from_kernel_thread+0x1b/0x28 [ 400.110028] [] ? __init_kthread_worker+0x60/0x60 [ 400.110028] Code: 89 43 08 69 c2 c0 03 00 00 89 da 89 0c 24 89 f1 05 00 b9 bd c0 e8 3e f4 ff ff f7 c7 00 02 00 00 74 1e e8 71 30 fb f0 [ 555.495732] SysRq : Show Locks Held [ 555.496596] [ 555.496596] Showing all locks held in the system: [ 555.521647] 1 lock held by agetty/1765: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1768: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1770: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1772: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1776: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1779: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by mingetty/1781: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by bash/1835: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by bash/1846: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] 1 lock held by bash/1870: [ 555.521647] #0: (&tty->atomic_read_lock){+.+...}, at: [] n_tty_read+0x462/0x700 [ 555.521647] [ 555.521647] ============================================= [ 555.521647] [ 592.518479] SysRq : Show backtrace of all active CPUs [ 592.519035] sending NMI to all CPUs: [ 592.519035] NMI backtrace for cpu 0 [ 592.519035] Pid: 1699, comm: btserver Tainted: G C 3.7.5+ #39 To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by. [ 592.519035] EIP: 0060:[] EFLAGS: 00000046 CPU: 0 [ 592.519035] EIP is at trace_hardirqs_off_caller+0x61/0x90 [ 592.519035] EAX: 00000000 EBX: c042e96d ECX: f1a6a380 EDX: 00000000 [ 592.519035] ESI: 03000000 EDI: 00000006 EBP: f1adfe10 ESP: f1adfe08 [ 592.519035] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 592.519035] CR0: 80050033 CR2: 08e5d000 CR3: 31ab5000 CR4: 000007e0 [ 592.519035] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 [ 592.519035] DR6: ffff0ff0 DR7: 00000400 [ 592.519035] Process btserver (pid: 1699, ti=f1ade000 task=f1a6a380 task.ti=f1ade000) [ 592.519035] Stack: [ 592.519035] 00000046 00000002 f1adfe18 c049aa7b f1adfe3c c042e96d c0bbe5d0 00000086 [ 592.519035] f1adfe48 00000800 00000000 c0bbe5d0 00000086 f1adfe48 c042e768 00000000 [ 592.519035] f1adfe58 c042ee74 c0abc65f 0000006c f1adfe60 c06fd9c8 f1adfe84 c06fdd3d [ 592.519035] Call Trace: [ 592.519035] [] trace_hardirqs_off+0xb/0x10 [ 592.519035] [] default_send_IPI_mask_logical+0xad/0x110 [ 592.519035] [] default_send_IPI_all+0x68/0x70 [ 592.519035] [] arch_trigger_all_cpu_backtrace+0x44/0x70 [ 592.519035] [] sysrq_handle_showallcpus+0x8/0x10 [ 592.519035] [] __handle_sysrq+0xed/0x140 [ 592.519035] [] handle_sysrq+0x20/0x30 [ 592.519035] [] serial8250_rx_chars+0xdf/0x1f0 [ 592.519035] [] ? _raw_spin_lock_irqsave+0x58/0x70 [ 592.519035] [] serial8250_handle_irq+0x81/0xa0 [ 592.519035] [] serial8250_default_handle_irq+0x17/0x20 [ 592.519035] [] serial8250_interrupt+0x4f/0xb0 [ 592.519035] [] handle_irq_event_percpu+0x46/0x150 [ 592.519035] [] handle_irq_event+0x37/0x60 [ 592.519035] [] handle_edge_irq+0x58/0x100 [ 592.519035] [] handle_irq+0x56/0xe0 [ 592.519035] [] do_IRQ+0x3d/0xb0 [ 592.519035] [] ? trace_hardirqs_on_caller+0xf4/0x180 [ 592.519035] [] common_interrupt+0x38/0x40 [ 592.519035] Code: 04 00 00 c7 81 5c 04 00 00 00 00 00 00 89 99 50 04 00 00 83 c0 01 89 81 48 04 00 00 89 81 58 04 00 00 5b 5d c3 90 8d [ 592.546178] NMI backtrace for cpu 1 [ 592.546178] Pid: 0, comm: swapper/1 Tainted: G C 3.7.5+ #39 To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by O. [ 592.546178] EIP: 0060:[] EFLAGS: 00000046 CPU: 1 [ 592.546178] EIP is at intel_idle+0x92/0x110 [ 592.546178] EAX: 00000030 EBX: d6bbf1a6 ECX: 00000001 EDX: 00000000 [ 592.546178] ESI: 12de00c7 EDI: 00000010 EBP: f5ca3f40 ESP: f5ca3f24 [ 592.546178] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 592.546178] CR0: 8005003b CR2: b77cd000 CR3: 00c83000 CR4: 000007e0 [ 592.546178] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 [ 592.546178] DR6: ffff0ff0 DR7: 00000400 [ 592.546178] Process swapper/1 (pid: 0, ti=f5ca2000 task=f5c758c0 task.ti=f5ca2000) [ 592.546178] Stack: [ 592.546178] 00000030 f79d975c 00000003 00000001 000000e4 c0bb9220 00000000 f5ca3f50 [ 592.546178] c0825746 f79d975c f79d975c f5ca3f5c c082576c c0bb9220 f5ca3f6c c0825cf9 [ 592.546178] c0beab50 00000000 f5ca3f88 c041390f 23aa8b50 0000000b d08e60b8 34fee705 [ 592.546178] Call Trace: [ 592.546178] [] cpuidle_enter+0x16/0x30 [ 592.546178] [] cpuidle_enter_state+0xc/0x40 [ 592.546178] [] cpuidle_idle_call+0x79/0xb0 [ 592.546178] [] cpu_idle+0xaf/0xf0 [ 592.546178] [] start_secondary+0x25e/0x264 [ 592.546178] Code: 08 8b 52 08 83 e2 08 75 22 31 d2 89 d1 0f 01 c8 0f ae f0 89 f6 89 e0 25 00 e0 ff ff 8b 40 08 a8 08 75 08 b1 01 8b 44 -- Ben Greear Candela Technologies Inc http://www.candelatech.com