Re: Panic in iwl3945 driver

Zhu Yi
2009-12-22T08:57:33Z

On Tue, 2009-12-22 at 00:40 +0800, Maxim Levitsky wrote:
> On Wed, 2009-12-02 at 19:17 +0200, Maxim Levitsky wrote:
> > On Wed, 2009-12-02 at 13:42 +0800, Zhu Yi wrote:
> > > On Tue, 2009-12-01 at 17:28 +0800, Zhu Yi wrote:
> > > > On Tue, 2009-12-01 at 06:35 +0800, Maxim Levitsky wrote:
> > > > > 0x000000000001668e <iwl3945_rx_reply_tx+302>: lea 0x38(%r8),%rdi
> > > > > 0x0000000000016692 <iwl3945_rx_reply_tx+306>: lea 0x4f(%r8),%rax
> > > >
> > > > When this happened, from your previous post, r8 is 0x0 and rdi is 0x38.
> > > > Since "info" is %rdi (see below), this means
> > > > txq->txb[txq->q.read_ptr].skb[0], aka. r8 is 0.
> > > >
> > > > > rate_idx = iwl3945_hwrate_to_plcp_idx(tx_resp->rate);
> > > > >
> > > > > 0x0000000000016696 <iwl3945_rx_reply_tx+310>: movb $0x0,0x9(%rdi) <---------- RIP
> > > > > 0x000000000001669a <iwl3945_rx_reply_tx+314>: movb $0x0,0xc(%rdi)
> > > > > 0x000000000001669e <iwl3945_rx_reply_tx+318>: movb $0x0,0xf(%rdi)
> > > > > 0x00000000000166a2 <iwl3945_rx_reply_tx+322>: movb $0x0,0x12(%rdi)
> > > > > 0x00000000000166a6 <iwl3945_rx_reply_tx+326>: movb $0x0,0x15(%rdi)
> > > >
> > > > This equals to below code in ieee80211_tx_info_clear_status(). "info" is
> > > > %rdi, which is 0x38. That matches NULL pointer dereference at 0x41 in
> > > > your oops header.
> > > >
> > > > for (i = 0; i < IEEE80211_TX_MAX_RATES; i++)
> > > > info->status.rates[i].count = 0;
> > > >
> > > > I guess there is a race for txq->q.read_ptr somewhere. Haven't checked
> > > > though.
> > >
> > > OK. 3945 updated write_ptr without regard to read_ptr on the Tx path.
> > > This messes up our TFD on high load. The patch should fix your problem.
> > >
> > > Signed-off-by: Zhu Yi <yi.zhu@intel.com>
> > >
> > > diff --git a/drivers/net/wireless/iwlwifi/iwl3945-base.c b/drivers/net/wireless/iwlwifi/iwl3945-base.c
> > > index 994db4a..b31b34c 100644
> > > --- a/drivers/net/wireless/iwlwifi/iwl3945-base.c
> > > +++ b/drivers/net/wireless/iwlwifi/iwl3945-base.c
> > > @@ -548,6 +548,9 @@ static int iwl3945_tx_skb(struct iwl_priv *priv, struct sk_buff *skb)
> > > txq = &priv->txq[txq_id];
> > > q = &txq->q;
> > >
> > > + if ((iwl_queue_space(q) < q->high_mark))
> > > + goto drop;
> > > +
> > > spin_lock_irqsave(&priv->lock, flags);
> > >
> > > idx = get_cmd_index(q, q->write_ptr, 0);
> > >
> > >
> Few days ago, I had an idea to reply here that I am sure that this
> problem disappeared with this patch.
>
>
> Today I got same kernel panic _with_ the patch applied....

Looks like (all of) the root causes are still not found yet. The symptom
is exactly the same as the previous one.

One thing I found today is when txq read_ptr catches up to write_ptr
(read_ptr == write_ptr), iwl_queue_used() will _always_ return TRUE!
This will be a problem if the firmware sends us a wrong index
(sequence), then we will fail the check in this condition. I'm not sure
if firmware can really send us a wrong sequence. Can you please try this
patch? Apply it on top of the previous one. If you do see the "FIRMWARE
BUG" in dmesg, then I think we find the root cause.

diff --git a/drivers/net/wireless/iwlwifi/iwl-dev.h b/drivers/net/wireless/iwlwifi/iwl-dev.h
index 2673e9a..02070cc 100644
--- a/drivers/net/wireless/iwlwifi/iwl-dev.h
+++ b/drivers/net/wireless/iwlwifi/iwl-dev.h
@@ -711,7 +711,11 @@ extern void iwl_txq_ctx_stop(struct iwl_priv *priv);
extern int iwl_queue_space(const struct iwl_queue *q);
static inline int iwl_queue_used(const struct iwl_queue *q, int i)
{
- return q->write_ptr > q->read_ptr ?
+ if (q->write_ptr == q->read_ptr)
+ printk("FIRMWARE BUG: index %d is given while read_ptr is %d\n",
+ i, q->read_ptr);
+
+ return q->write_ptr >= q->read_ptr ?
(i >= q->read_ptr && i < q->write_ptr) :
!(i < q->read_ptr && i >= q->write_ptr);
}

Thanks,
-yi

> <1>[ 3075.773505] BUG: unable to handle kernel NULL pointer dereference at 0000000000000041
> <1>[ 3075.773540] IP: [<ffffffffa0c175f6>] iwl3945_rx_reply_tx+0xc6/0x450 [iwl3945]
> <4>[ 3075.773564] PGD 0
> <1>[ 3075.773570] Thread overran stack, or stack corrupted
> <0>[ 3075.773579] Oops: 0002 [#1] PREEMPT SMP
> <0>[ 3075.773591] last sysfs file: /sys/devices/platform/coretemp.1/temp1_input
> <4>[ 3075.773604] CPU 0
> <4>[ 3075.773611] Modules linked in: af_packet nfsd exportfs nfs lockd nfs_acl auth_rpcgss sunrpc snd_hda_codec_realtek uvcvideo videodev iwl3945 cpufreq_powersave usb_storage v4l1_compat snd_hda_intel iwlcore cpufreq_conservative joydev usb_libusual v4l2_compat_ioctl32 snd_hda_codec cpufreq_userspace mac80211 acpi_cpufreq uhci_hcd coretemp snd_hwdep cfg80211 psmouse tg3 ohci1394 video ehci_hcd snd_pcm sbp2 ac battery output usbcore libphy snd_page_alloc lirc_ene0100 ieee1394 nvidia(P) serio_raw evdev rfkill fuse lzo lzo_decompress lzo_compress
> <6>[ 3075.773757] Pid: 0, comm: swapper Tainted: P 2.6.32-wl #225 Aspire 5720
> <6>[ 3075.773772] RIP: 0010:[<ffffffffa0c175f6>] [<ffffffffa0c175f6>] iwl3945_rx_reply_tx+0xc6/0x450 [iwl3945]
> <6>[ 3075.773795] RSP: 0018:ffff880002203d20 EFLAGS: 00010246
> <6>[ 3075.773806] RAX: 000000000000004f RBX: ffff880065121600 RCX: 00000000000000b0
> <6>[ 3075.773820] RDX: ffffffffa0c1f220 RSI: ffff88004f42e008 RDI: 0000000000000038
> <6>[ 3075.773834] RBP: ffff880002203d90 R08: 0000000000000000 R09: 0000000000000100
> <6>[ 3075.773847] R10: 0000000000000001 R11: 0000000000000046 R12: 00000000000000a0
> <6>[ 3075.773861] R13: 0000000000000002 R14: 00000000000000b0 R15: 0000000000020201
> <6>[ 3075.773875] FS: 0000000000000000(0000) GS:ffff880002200000(0000) knlGS:0000000000000000
> <6>[ 3075.773891] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
> <6>[ 3075.773903] CR2: 0000000000000041 CR3: 0000000001001000 CR4: 00000000000006f0
> <6>[ 3075.773917] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> <6>[ 3075.773930] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> <4>[ 3075.773945] Process swapper (pid: 0, threadinfo ffffffff815b8000, task ffffffff815bcb60)
> <0>[ 3075.773959] Stack:
> <4>[ 3075.773964] ffff880065122070 0000000000000046 ffff880002203d40 0000000000000046
> <4>[ 3075.773981] <0> 0000000000000282 0000000000000282 0000000000000282 ffff880065122010
> <4>[ 3075.774000] <0> ffff880002203d70 ffff880065121600 ffff880065122eb0 ffff88004f42e000
> <0>[ 3075.774020] Call Trace:
> <0>[ 3075.774026] <IRQ>
> <4>[ 3075.774037] [<ffffffffa0c0acf7>] iwl3945_irq_tasklet+0x657/0x1740 [iwl3945]
> <4>[ 3075.774060] [<ffffffffa09b883e>] ? iwl_isr_legacy+0x3e/0x600 [iwlcore]
> <4>[ 3075.774077] [<ffffffff81053f86>] tasklet_action+0x106/0x110
> <4>[ 3075.774090] [<ffffffff810556a4>] __do_softirq+0x114/0x2c0
> <4>[ 3075.774103] [<ffffffff8109eb68>] ? handle_edge_irq+0x78/0x160
> <4>[ 3075.774117] [<ffffffff8100d25c>] call_softirq+0x1c/0x30
> <4>[ 3075.774128] [<ffffffff8100f1fd>] do_softirq+0x7d/0xb0
> <4>[ 3075.774140] [<ffffffff81055155>] irq_exit+0x95/0xa0
> <4>[ 3075.774152] [<ffffffff814031fc>] do_IRQ+0x7c/0xf0
> <4>[ 3075.774165] [<ffffffff8100ca13>] ret_from_intr+0x0/0xf
> <0>[ 3075.774175] <EOI>
> <4>[ 3075.774183] [<ffffffff8129996a>] ? acpi_idle_enter_bm+0x275/0x2aa
> <4>[ 3075.774196] [<ffffffff81299974>] ? acpi_idle_enter_bm+0x27f/0x2aa
> <4>[ 3075.774209] [<ffffffff8129996a>] ? acpi_idle_enter_bm+0x275/0x2aa
> <4>[ 3075.774224] [<ffffffff8132996f>] ? cpuidle_idle_call+0x9f/0x160
> <4>[ 3075.774237] [<ffffffff8100b1df>] ? cpu_idle+0xaf/0x110
> <4>[ 3075.774250] [<ffffffff813eca3a>] ? rest_init+0x7a/0x80
> <4>[ 3075.774264] [<ffffffff8162dd01>] ? start_kernel+0x3ac/0x3b8
> <4>[ 3075.774277] [<ffffffff8162d315>] ? x86_64_start_reservations+0x125/0x129
> <4>[ 3075.774291] [<ffffffff8162d3fd>] ? x86_64_start_kernel+0xe4/0xeb
> <0>[ 3075.774302] Code: 00 41 39 ce 0f 8d e3 01 00 00 48 8b 47 40 48 63 d2 48 69 d2 98 00 00 00 4c 8b 04 02 48 c7 c2 20 f2 c1 a0 49 8d 78 38 49 8d 40 4f <c6> 47 09 00 c6 47 0c 00 c6 47 0f 00 c6 47 12 00 c6 47 15 00 49
> <1>[ 3075.774394] RIP [<ffffffffa0c175f6>] iwl3945_rx_reply_tx+0xc6/0x450 [iwl3945]
> <4>[ 3075.774412] RSP <ffff880002203d20>
> <0>[ 3075.774420] CR2: 0000000000000041
> <4>[ 3075.774429] ---[ end trace 7ea524291c193896 ]---
> <0>[ 3075.774439] Kernel panic - not syncing: Fatal exception in interrupt
> <4>[ 3075.774451] Pid: 0, comm: swapper Tainted: P D 2.6.32-wl #225
> <4>[ 3075.774463] Call Trace:
> <4>[ 3075.774469] <IRQ> [<ffffffff813fe515>] panic+0x82/0x13f
> <4>[ 3075.774486] [<ffffffff81010a52>] oops_end+0xe2/0xf0
> <4>[ 3075.774497] [<ffffffff81031382>] no_context+0xf2/0x260
> <4>[ 3075.774509] [<ffffffff81031615>] __bad_area_nosemaphore+0x125/0x1e0
> <4>[ 3075.774523] [<ffffffff810316e3>] bad_area_nosemaphore+0x13/0x20
> <4>[ 3075.774536] [<ffffffff81031aca>] do_page_fault+0x26a/0x320
> <4>[ 3075.774549] [<ffffffff81402dcf>] page_fault+0x1f/0x30
> <4>[ 3075.774564] [<ffffffffa0c175f6>] ? iwl3945_rx_reply_tx+0xc6/0x450 [iwl3945]
> <4>[ 3075.774581] [<ffffffffa0c0acf7>] iwl3945_irq_tasklet+0x657/0x1740 [iwl3945]
> <4>[ 3075.774602] [<ffffffffa09b883e>] ? iwl_isr_legacy+0x3e/0x600 [iwlcore]
> <4>[ 3075.774616] [<ffffffff81053f86>] tasklet_action+0x106/0x110
> <4>[ 3075.774628] [<ffffffff810556a4>] __do_softirq+0x114/0x2c0
> <4>[ 3075.774640] [<ffffffff8109eb68>] ? handle_edge_irq+0x78/0x160
> <4>[ 3075.774653] [<ffffffff8100d25c>] call_softirq+0x1c/0x30
> <4>[ 3075.774665] [<ffffffff8100f1fd>] do_softirq+0x7d/0xb0
> <4>[ 3075.774676] [<ffffffff81055155>] irq_exit+0x95/0xa0
> <4>[ 3075.774687] [<ffffffff814031fc>] do_IRQ+0x7c/0xf0
> <4>[ 3075.774698] [<ffffffff8100ca13>] ret_from_intr+0x0/0xf
> <4>[ 3075.774708] <EOI> [<ffffffff8129996a>] ? acpi_idle_enter_bm+0x275/0x2aa
> <4>[ 3075.774726] [<ffffffff81299974>] ? acpi_idle_enter_bm+0x27f/0x2aa
> <4>[ 3075.774739] [<ffffffff8129996a>] ? acpi_idle_enter_bm+0x275/0x2aa
> <4>[ 3075.774752] [<ffffffff8132996f>] ? cpuidle_idle_call+0x9f/0x160
> <4>[ 3075.774765] [<ffffffff8100b1df>] ? cpu_idle+0xaf/0x110
> <4>[ 3075.774777] [<ffffffff813eca3a>] ? rest_init+0x7a/0x80
> <4>[ 3075.774789] [<ffffffff8162dd01>] ? start_kernel+0x3ac/0x3b8
> <4>[ 3075.774802] [<ffffffff8162d315>] ? x86_64_start_reservations+0x125/0x129
> <4>[ 3075.774816] [<ffffffff8162d3fd>] ? x86_64_start_kernel+0xe4/0xeb
> <0>[ 3075.774845] Rebooting in 10 seconds..
>
>
>
> (gdb) info line *iwl3945_rx_reply_tx+0xc6
> Line 483 of "/home/maxim/software/kernel/linux-2.6/include/net/mac80211.h"
> starts at address 0x16626 <iwl3945_rx_reply_tx+198> and ends at 0x1663a <iwl3945_rx_reply_tx+218>.
>
>
> (gdb) list * 0x16626
> 0x16626 is in iwl3945_rx_reply_tx (/home/maxim/software/kernel/linux-2.6/include/net/mac80211.h:483).
> 478 BUILD_BUG_ON(offsetof(struct ieee80211_tx_info, status.rates) !=
> 479 offsetof(struct ieee80211_tx_info, driver_rates));
> 480 BUILD_BUG_ON(offsetof(struct ieee80211_tx_info, status.rates) != 8);
> 481 /* clear the rate counts */
> 482 for (i = 0; i < IEEE80211_TX_MAX_RATES; i++)
> 483 info->status.rates[i].count = 0;
> 484
> 485 BUILD_BUG_ON(
> 486 offsetof(struct ieee80211_tx_info, status.ampdu_ack_len) != 23);
> 487 memset(&info->status.ampdu_ack_len, 0,
>
>
>
> Kernel is the dbb6e436ef8e1713258bf1218d09e927d8de3590
> (wireless: update old static regulatory domain rules)
>
> Plus few patches that only one that touches wireless is:
>
>
> diff --git a/drivers/net/wireless/iwlwifi/iwl3945-base.c b/drivers/net/wireless/iwlwifi/iwl3945-base.c
> index 2a28a1f..a36de73 100644
> --- a/drivers/net/wireless/iwlwifi/iwl3945-base.c
> +++ b/drivers/net/wireless/iwlwifi/iwl3945-base.c
> @@ -548,6 +548,9 @@ static int iwl3945_tx_skb(struct iwl_priv *priv, struct sk_buff *skb)
> txq = &priv->txq[txq_id];
> q = &txq->q;
>
> + if ((iwl_queue_space(q) < q->high_mark))
> + goto drop;
> +
> spin_lock_irqsave(&priv->lock, flags);
>
> idx = get_cmd_index(q, q->write_ptr, 0);
>
>
>
> Best regards,
> Maxim Levitsky
>
>