Hi,
The following test script triggers a memory leak:
insmod mwifiex_sdio.ko
sleep 1
ifconfig eth0 up
iwlist eth0 scan &
sleep 0.5
rmmod mwifiex_sdio
kmemleak says:
unreferenced object 0xed8bb200 (size 512):
comm "iwlist", pid 666, jiffies 4294952762 (age 16.330s)
hex dump (first 32 bytes):
00 00 00 00 00 00 00 00 00 e8 b8 8b ed 01 01 00 ................
01 00 00 00 00 00 02 00 01 00 00 00 00 00 03 00 ................
backtrace:
[<c00a7f1c>] create_object+0x118/0x2b0
[<c03db82c>] kmemleak_alloc+0x80/0xc4
[<c00a3444>] kmem_cache_alloc+0xa8/0x110
[<c022f8ac>] mwifiex_cfg80211_scan+0xc0/0x300
[<c03bfe2c>] cfg80211_wext_siwscan+0x280/0x2f8
[<c03d7cf8>] ioctl_standard_call+0x290/0x3b8
[<c03d7f14>] wext_handle_ioctl+0xf4/0x1c0
[<c0308d70>] dev_ioctl+0x6b4/0x6dc
[<c02f3f00>] sock_ioctl+0x254/0x28c
[<c00b994c>] vfs_ioctl+0x30/0x44
[<c00ba504>] do_vfs_ioctl+0x560/0x5b8
[<c00ba59c>] sys_ioctl+0x40/0x68
[<c000eb40>] ret_fast_syscall+0x0/0x30
[<ffffffff>] 0xffffffff
The test environment is XO-4 running Linux 3.8
(http://wiki.laptop.org/go/User:DanielDrake/Run_upstream_kernel_on_XO-4).
NetworkManager can be enabled or disabled (doesn't matter) and the
driver is hacked to remove p2p0 and uap0 interfaces. And these patches
are applied:
mwifiex: fix race when queuing commands
mwifiex: skip pending commands after function shutdown
mwifiex: cancel cmd timer and free curr_cmd in shutdown process
mwifiex: fix negative cmd_pending count
mwifiex: complete last internal scan
I'm relatively sure this issue is old and not related to those patches
so I'm creating a new thread for it.
Thanks
Daniel
On Thu, Apr 25, 2013 at 4:50 PM, Bing Zhao <[email protected]> wrote:
> Hi Daniel,
>
>> While I don't have an explanation for why kmemleak didn't detect this
>> before, I have confirmed with some simple printks that mwifiex does
>> not call free_netdev on the netdev that it allocates, at least when
>> using the test script posted earlier in this thread. So that is
>> another leak that must be fixed.
>
> Yes it is. Attached is a patch from Amitkumar Karwar to fix it.
Thanks. This seems to be working, and makes kmemleak happy.
So when we find a race-free way to free user_scan_cfg, we can probably
end this topic.
> One scan request from cfg80211 is split to multiple scan commands being sent from driver to firmware.
> If scan_request is cleared (e.g. mwifiex_close) during a scan command processing, all pending scan commands will be aborted after getting response of previous scan command, and scan_delay_timer is modified to fire in 50ms.
>
> With original script (mwifiex_sdio is removed), I don't see scan_delay_timer_fn() gets triggered either. My assumption is that the scan_pending_q has already been emptied, so we don't run into the same path as above.
So far I have not managed to get scan_delay_timer_fn() to execute at
all - even when I am not using that script. But I have not really
diagnosed why. I was wondering if there's anything obvious I might be
missing.
Thanks
Daniel
Hi Daniel,
> Thanks. This seems to be working, and makes kmemleak happy.
Thanks for testing.
> So when we find a race-free way to free user_scan_cfg, we can probably
> end this topic.
Please find attached Amitkumar's patch that addresses this issue. I tested it on my Chromebook.
If it works for you on XO-4 I will rebase both patches and resend to the list.
> So far I have not managed to get scan_delay_timer_fn() to execute at
> all - even when I am not using that script. But I have not really
> diagnosed why. I was wondering if there's anything obvious I might be
> missing.
Here's how I can get scan_delay_timer_fn() trigged on my Chromebook:
0) boot up and switch to a shell console
1) stop wpasupplicant; stop shill # stop my Connection Manager
2) ifconfig mlan0 up
3) iwlist mlan0 scan & sleep 1; ifconfig mlan0 down
Thanks,
Bing
>
> Thanks
> Daniel
Hi Daniel,
> Hi,
>
> The following test script triggers a memory leak:
>
> insmod mwifiex_sdio.ko
> sleep 1
> ifconfig eth0 up
> iwlist eth0 scan &
> sleep 0.5
> rmmod mwifiex_sdio
>
> kmemleak says:
> unreferenced object 0xed8bb200 (size 512):
> comm "iwlist", pid 666, jiffies 4294952762 (age 16.330s)
> hex dump (first 32 bytes):
> 00 00 00 00 00 00 00 00 00 e8 b8 8b ed 01 01 00 ................
> 01 00 00 00 00 00 02 00 01 00 00 00 00 00 03 00 ................
> backtrace:
> [<c00a7f1c>] create_object+0x118/0x2b0
> [<c03db82c>] kmemleak_alloc+0x80/0xc4
> [<c00a3444>] kmem_cache_alloc+0xa8/0x110
> [<c022f8ac>] mwifiex_cfg80211_scan+0xc0/0x300
> [<c03bfe2c>] cfg80211_wext_siwscan+0x280/0x2f8
> [<c03d7cf8>] ioctl_standard_call+0x290/0x3b8
> [<c03d7f14>] wext_handle_ioctl+0xf4/0x1c0
> [<c0308d70>] dev_ioctl+0x6b4/0x6dc
> [<c02f3f00>] sock_ioctl+0x254/0x28c
> [<c00b994c>] vfs_ioctl+0x30/0x44
> [<c00ba504>] do_vfs_ioctl+0x560/0x5b8
> [<c00ba59c>] sys_ioctl+0x40/0x68
> [<c000eb40>] ret_fast_syscall+0x0/0x30
> [<ffffffff>] 0xffffffff
Thanks for reporting this issue.
Please find attached the patch and try it on your XO4.
I will resend the patch to the list if it works for you.
Thanks,
Bing
Hi,
On Mon, Apr 22, 2013 at 7:50 PM, Bing Zhao <[email protected]> wrote:
> Thanks for reporting this issue.
> Please find attached the patch and try it on your XO4.
>
> I will resend the patch to the list if it works for you.
This does seem to make the kmemleak report go away.
However, strangely, it seems to make a whole bunch of kmemleak reports
*appear*, as if the struct netdev is not being destroyed, and more. I
guess this could just be a kmemleak oddity but it is strange that it
did not appear before this patch.
Trying to look for possible causes (memory corruption?), I can't see
any code that serializes scan_delay_timer_fn with mwifiex_close(), so
mwifiex_close freeing the scan data while scan_delay_timer_fn is using
it could cause badness to happen. However I haven't yet figured out
how to trigger scan_delay_timer_fn to execute even once (any tips?).
The fact that scan_delay_timer_fn isn't executing at all means that
its not related to the kmemleak oddness, which must have another cause
or explanation.
I will investigate more tomorrow.
Thanks
Daniel
Hi Daniel,
> It makes me uneasy that you are prepping the driver to have this timer
> still running after mwifiex_close() is called.
When mwifiex_close() is called a scan command can be still in processing.
We have to wait for the scan command response from firmware before the remaining scan commands can be cleaned up. Once the command response is back the scan timer gets called to cleanup the scan.
> Anyway, if you do want to go this route,
> I think there is no need to add is_ndo_stop.
We will need a flag to indicate that the current scan request is being aborted.
'is_ndo_stop' is not a good name though. In attached revised patch, it's been renamed to 'scan_aborting'.
> You should be able to query the net layer for its state. Maybe
> netif_running() will do the trick.
The netif_running state may not be accurate as the use can bring the interface up again shortly.
Even if user does 'ifconfig eth0 up' again, we still need to continue the scan abort processing.
>
> I'll await your comments on that before testing.
Please test the revision attached with this e-mail.
Thanks,
Bing
>
> Thanks
> Daniel
Hi Daniel,
> While I don't have an explanation for why kmemleak didn't detect this
> before, I have confirmed with some simple printks that mwifiex does
> not call free_netdev on the netdev that it allocates, at least when
> using the test script posted earlier in this thread. So that is
> another leak that must be fixed.
Yes it is. Attached is a patch from Amitkumar Karwar to fix it.
> > Trying to look for possible causes (memory corruption?), I can't see
> > any code that serializes scan_delay_timer_fn with mwifiex_close(), so
> > mwifiex_close freeing the scan data while scan_delay_timer_fn is using
> > it could cause badness to happen. However I haven't yet figured out
> > how to trigger scan_delay_timer_fn to execute even once (any tips?).
>
> I still haven't figured out how to make this code trigger, but I
> looked again, and I do believe there is a potential crash waiting for
> us here, because there is no serialization between mwifiex_close and
> the possible running of this timer (which uses user_scan_cfg).
One scan request from cfg80211 is split to multiple scan commands being sent from driver to firmware.
If scan_request is cleared (e.g. mwifiex_close) during a scan command processing, all pending scan commands will be aborted after getting response of previous scan command, and scan_delay_timer is modified to fire in 50ms.
With original script (mwifiex_sdio is removed), I don't see scan_delay_timer_fn() gets triggered either. My assumption is that the scan_pending_q has already been emptied, so we don't run into the same path as above.
>
> Also, I found another issue. Change the script to:
>
> insmod mwifiex_sdio.ko
> sleep 1
> ifconfig eth0 up
> iwlist eth0 scan &
> sleep 0.1
> ifconfig eth0 down
With this new script (eth0 is down), I can easily see scan_delay_timer_fn() gets called.
The scan_pending_q is not emptied in this case.
>
> and add printk's in mwifiex_close (where user_scan_cfg is freed) and
> in mwifiex_cfg80211_scan() (where user_cfg_cfg is used and also
> freed). You can see that mwifiex_cfg80211_scan() executes at the same
> time as mwifiex_close() (and several times after) and I can't see any
> serialization here, so I think there are some other crashes here as
> well (e.g. looks like it could race and we could double-free
> user_scan_cfg).
Sorry, it's my bad. I realized that my patch to cleanup user_scan_cfg in mwifiex_close() is wrong and it will cause this problem.
Please wait for another patch that fixes the memory leak in mwifiex_cfg80211_scan.
Thanks,
Bing
>
> Thanks
> Daniel
On Fri, Apr 26, 2013 at 12:28 PM, Bing Zhao <[email protected]> wrote:
> Please find attached Amitkumar's patch that addresses this issue. I tested it on my Chromebook.
> If it works for you on XO-4 I will rebase both patches and resend to the list.
It makes me uneasy that you are prepping the driver to have this timer
still running after mwifiex_close() is called. Anyway, if you do want
to go this route, I think there is no need to add is_ndo_stop. You
should be able to query the net layer for its state. Maybe
netif_running() will do the trick.
I'll await your comments on that before testing.
Thanks
Daniel
On Wed, Apr 24, 2013 at 4:48 PM, Daniel Drake <[email protected]> wrote:
> However, strangely, it seems to make a whole bunch of kmemleak reports
> *appear*, as if the struct netdev is not being destroyed, and more. I
> guess this could just be a kmemleak oddity but it is strange that it
> did not appear before this patch.
While I don't have an explanation for why kmemleak didn't detect this
before, I have confirmed with some simple printks that mwifiex does
not call free_netdev on the netdev that it allocates, at least when
using the test script posted earlier in this thread. So that is
another leak that must be fixed.
> Trying to look for possible causes (memory corruption?), I can't see
> any code that serializes scan_delay_timer_fn with mwifiex_close(), so
> mwifiex_close freeing the scan data while scan_delay_timer_fn is using
> it could cause badness to happen. However I haven't yet figured out
> how to trigger scan_delay_timer_fn to execute even once (any tips?).
I still haven't figured out how to make this code trigger, but I
looked again, and I do believe there is a potential crash waiting for
us here, because there is no serialization between mwifiex_close and
the possible running of this timer (which uses user_scan_cfg).
Also, I found another issue. Change the script to:
insmod mwifiex_sdio.ko
sleep 1
ifconfig eth0 up
iwlist eth0 scan &
sleep 0.1
ifconfig eth0 down
and add printk's in mwifiex_close (where user_scan_cfg is freed) and
in mwifiex_cfg80211_scan() (where user_cfg_cfg is used and also
freed). You can see that mwifiex_cfg80211_scan() executes at the same
time as mwifiex_close() (and several times after) and I can't see any
serialization here, so I think there are some other crashes here as
well (e.g. looks like it could race and we could double-free
user_scan_cfg).
Thanks
Daniel
On Mon, May 6, 2013 at 12:42 PM, Bing Zhao <[email protected]> wrote:
> There are two different static mwifiex_free_adapter() functions which cause confusion.
> The 1/2 patch renames the one in init.c to mwifiex_adapter_cleanup().
Thanks, that was confusing indeed.
With these patches I can't trigger any further crashes.
I think you should use del_timer_sync() though, for the SMP case where
the timer may be running on a different processor.
Daniel
Hi Daniel,
> Kernel panic - not syncing: Fatal exception in interrupt
>
> I suspect this crash also existed before your patch, just I was not
> testing scan_delay_fn before. Maybe you prefer to deal with it as a
> separate issue.
You are right, this crash also existed before the patch in "deferred scan" path.
Please try attached patch address this issue.
Thanks,
Bing
>
> Daniel
Hi Daniel,
> > Thanks for the comment. Please find attached updated patch.
>
> This looks better, thanks.
I will post these patches to the list after the 3.10 merge window.
905c907 mwifiex: scan delay timer cleanup in unload path
a11b504 mwifiex: rename mwifiex_free_adapter() routine in init.c
7841fa6 mwifiex: remove global user_scan_cfg variable
Thanks,
Bing
>
> Daniel
Hi Daniel,
> I think you should use del_timer_sync() though, for the SMP case where
> the timer may be running on a different processor.
Thanks for the comment. Please find attached updated patch.
Regards,
Bing
>
> Daniel
On Tue, Apr 30, 2013 at 12:26 PM, Bing Zhao <[email protected]> wrote:
> Please test the revision attached with this e-mail.
It works with the original test case. Thanks. In that environment, for
whatever reason, scan_delay_fn is not triggered.
However, I think we both agree that scan_delay_fn can (and will)
'legally' execute during the above test (and you did mention earlier
that in your env it is being called). I can see that some conditions
must be met for this to happen, defined in mwifiex_ret_802_11_scan().
To simplify my testing I just "relaxed" those conditions to be:
- } else if (!mwifiex_wmm_lists_empty(adapter) &&
- (priv->scan_request && (priv->scan_request->flags &
- NL80211_SCAN_FLAG_LOW_PRIORITY))) {
+ } else if (1) {
Now it always triggers. A good way to get some solid testing of this codepath.
And as I suspected, running my test now causes an immediate kernel crash.
bash-4.2# bash test.sh
mwifiex_sdio mmc0:0001:1: WLAN FW already running! Skip FW dnld
lis3lv02d_i2c 4-0019: Failed to get supply 'Vdd': -517
i2c 4-0019: Driver lis3lv02d_i2c requests probe deferral
mwifiex_sdio mmc0:0001:1: WLAN FW is active
mwifiex_sdio mmc0:0001:1: ignoring F/W country code US
mwifiex_sdio mmc0:0001:1: driver_version = mwifiex 1.0 (14.66.9.p96)
systemd-udevd[474]: renamed network interface mlan0 to eth0
mwifiex_sdio mmc0:0001:1: info: mwifiex_ret_802_11_scan: deferring scan
mwifiex_sdio mmc0:0001:1: info: mwifiex_ret_802_11_scan: deferring scan
eth0 Failed to read scan data : No such device
Unable to handle kernel paging request at virtual address 00100100
pgd = c0004000
[00100100] *pgd=00000000
Internal error: Oops: 15 [#1] PREEMPT ARM
Modules linked in: [last unloaded: mwifiex_sdio]
CPU: 0 Not tainted (3.8.0-00021-gd431a65-dirty #992)
PC is at scan_delay_timer_fn+0x1dc/0x2a0
LR is at call_timer_fn.isra.36+0x2c/0x94
pc : [<c021b2a0>] lr : [<c002a158>] psr: 600f0193
sp : c054fe50 ip : c054fe78 fp : c054fe74
r10: 3fa6bf3c r9 : 00200000 r8 : c0594080
r7 : c021b0c4 r6 : 00100100 r5 : ed4fc000 r4 : edbce000
r3 : c054e000 r2 : 600f0113 r1 : 00000103 r0 : 0000000a
Flags: nZCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment kernel
Control: 10c5387d Table: 2d888059 DAC: 00000015
Process swapper (pid: 0, stack limit = 0xc054e240)
Stack: (0xc054fe50 to 0xc0550000)
fe40: c054e000 00000102 ed4fc000 c021b0c4
fe60: c0594080 3fa6bf3c c054fe9c c054fe78 c002a158 c021b0d0 0000000d 00000001
fe80: c0594200 c054e000 ed4fc000 c021b0c4 c054fec4 c054fea0 c002a36c c002a138
fea0: c054fea0 c054fea0 00000001 c05940c8 c054e000 00000102 c054ff0c c054fec8
fec0: c0023de8 c002a1cc 00000000 ee004740 c054feec 00000004 00000001 0000000a
fee0: c054ff04 0000000d 00000000 fe282104 c054ff7c 00004059 562f5842 00000000
ff00: c054ff1c c054ff10 c00241a0 c0023d48 c054ff34 c054ff20 c000fa98 c0024160
ff20: c000fcac 600f0013 c054ff44 c054ff38 c0008250 c000fa38 c054ffa4 c054ff48
ff40: c000e6cc c000824c 00000000 c055dbd8 00000000 00000000 c054e000 c0581348
ff60: c0531198 c15f5a00 00004059 562f5842 00000000 c054ffa4 c054ff90 c054ff90
ff80: c000fb4c c000fcac 600f0013 ffffffff 00000002 00000000 c054ffbc c054ffa8
ffa0: c03da988 c000fc5c c055acd0 c05560d8 c054fff4 c054ffc0 c050f7ec c03da924
ffc0: ffffffff ffffffff c050f2dc 00000000 00000000 c0531198 10c5387d c0556024
ffe0: c0531194 c05598e4 00000000 c054fff8 00008074 c050f558 00000000 00000000
Backtrace:
[<c021b0c4>] (scan_delay_timer_fn+0x0/0x2a0) from [<c002a158>]
(call_timer_fn.isra.36+0x2c/0x94)
[<c002a12c>] (call_timer_fn.isra.36+0x0/0x94) from [<c002a36c>]
(run_timer_softirq+0x1ac/0x22c)
r7:c021b0c4 r6:ed4fc000 r5:c054e000 r4:c0594200
[<c002a1c0>] (run_timer_softirq+0x0/0x22c) from [<c0023de8>]
(__do_softirq+0xac/0x174)
r7:00000102 r6:c054e000 r5:c05940c8 r4:00000001
[<c0023d3c>] (__do_softirq+0x0/0x174) from [<c00241a0>] (irq_exit+0x4c/0xb0)
[<c0024154>] (irq_exit+0x0/0xb0) from [<c000fa98>] (handle_IRQ+0x6c/0x8c)
[<c000fa2c>] (handle_IRQ+0x0/0x8c) from [<c0008250>] (asm_do_IRQ+0x10/0x14)
r5:600f0013 r4:c000fcac
[<c0008240>] (asm_do_IRQ+0x0/0x14) from [<c000e6cc>] (__irq_svc+0x4c/0x94)
Exception stack(0xc054ff48 to 0xc054ff90)
ff40: 00000000 c055dbd8 00000000 00000000 c054e000 c0581348
ff60: c0531198 c15f5a00 00004059 562f5842 00000000 c054ffa4 c054ff90 c054ff90
ff80: c000fb4c c000fcac 600f0013 ffffffff
[<c000fc50>] (cpu_idle+0x0/0xa4) from [<c03da988>] (rest_init+0x70/0x88)
r5:00000000 r4:00000002
[<c03da918>] (rest_init+0x0/0x88) from [<c050f7ec>] (start_kernel+0x2a0/0x2f0)
r4:c05560d8 r3:c055acd0
[<c050f54c>] (start_kernel+0x0/0x2f0) from [<00008074>] (0x8074)
Code: e5931004 e2811001 e5831004 e5946a5c (e8960003)
---[ end trace 5842e4d79510ea17 ]---
Kernel panic - not syncing: Fatal exception in interrupt
I suspect this crash also existed before your patch, just I was not
testing scan_delay_fn before. Maybe you prefer to deal with it as a
separate issue.
Daniel
On Thu, May 2, 2013 at 12:41 PM, Bing Zhao <[email protected]> wrote:
> You are right, this crash also existed before the patch in "deferred scan" path.
> Please try attached patch address this issue.
I haven't tested it yet, but it doesn't look like a fix to me.
Surely the crash here is that the timer_fn is running and using data
that has been freed, like the netdev and the workqueue.
mwifiex_free_adapter() is called at the end of mwifiex_remove_card(),
after it has freed a whole load of that stuff. If you are trying to
stop the timer at this point, you are way too late.
Daniel
Hi Daniel,
> I haven't tested it yet, but it doesn't look like a fix to me.
>
> Surely the crash here is that the timer_fn is running and using data
> that has been freed, like the netdev and the workqueue.
Please try attached patches instead.
> mwifiex_free_adapter() is called at the end of mwifiex_remove_card(),
> after it has freed a whole load of that stuff. If you are trying to
> stop the timer at this point, you are way too late.
There are two different static mwifiex_free_adapter() functions which cause confusion.
The 1/2 patch renames the one in init.c to mwifiex_adapter_cleanup().
Thanks,
Bing
>
> Daniel
On Wed, May 8, 2013 at 11:58 AM, Bing Zhao <[email protected]> wrote:
> Thanks for the comment. Please find attached updated patch.
This looks better, thanks.
Daniel