Re: [Acx100-devel] kmemleak, locking issue.

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

On 05/23/2012 11:44 AM, Jim Cromie wrote:
> hi Oliver, Larry,
>
> Ive recently been seeing more noise on my console,
> for a hand-wavy definition of recent.
>
> At first, I thought it might be the __acquire/__release trick,
> but that doesnt quite fit -
> I built with -f Makefile.nomem, and that build does NOT
> get the logs below.
>
> I recently added KMEMLEAK to my kernel, do you have that
> on yours ?  Would you add it to one of your test-boxes,
> see if you get same reports ?
>
> I'll try on my desktop too, the 586 box box Im using is somewhat
> limited in Disk and memory, and a KERNEL_DEBUG build is pretty big.
>
>
> acxusb.acxusb_init_module: built with CONFIG_ACX_MAC80211_USB
> acxusb.acxusb_init_module: USB module initialized, probing for devices...
> usbcore: registered new interface driver acx_usb
> acx.acxmem_init_module: built with CONFIG_ACX_MAC80211_MEM
> acx.acxmem_init_module: compiled to use 32bit I/O access. I/O timing
> issues might occur, such as non-working firmware upload. Report them
> acx.acxmem_init_module: acx: running on a little-endian CPU
> acx: Slave-memory module initialized, waiting for cards to probe...
> BUG: unable to handle kernel paging request at c88f9000
> IP: [<c02f68fe>] crc32_body+0x4e/0xf8
> *pde = 069fa067 *pte = 00000000
> Oops: 0000 [#1] PREEMPT
> Modules linked in: arc4 acx_mac80211(O) rtl8180 mac80211 eeprom_93cx6
> scx200 cfg80211 ohci_hcd pata_sc1200
>
> Pid: 31, comm: kmemleak Tainted: G           O 3.4.0-rc5-ske+ #64
> EIP: 0060:[<c02f68fe>] EFLAGS: 00010097 CPU: 0
> EIP is at crc32_body+0x4e/0xf8
> EAX: 00000000 EBX: c06371c0 ECX: 00000000 EDX: c88f9000
> ESI: c88f9000 EDI: 00000286 EBP: c4ec7f54 ESP: c4ec7f38
>   DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
> CR0: 8005003b CR2: c88f9000 CR3: 03d52000 CR4: 00000000
> DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> DR6: ffff0ff0 DR7: 00000400
> Process kmemleak (pid: 31, ti=c4ec6000 task=c4c75280 task.ti=c4ec6000)
> Stack:
>   00000286 c88f8ffc 0000028f 00000007 c4513000 00000000 00000286 c4ec7f60
>   c02f69e6 c06371c0 c4ec7f80 c01cbf39 00000000 c047336e c451302c 000249f0
>   00000000 c01cc05f c4ec7f90 c01cc0ba c05b27c0 c7047ef8 c4ec7fe4 c0134119
> Call Trace:
>   [<c02f69e6>] crc32_le+0x12/0x14
>   [<c01cbf39>] kmemleak_scan+0x23f/0x365
>   [<c047336e>] ? mutex_lock_nested+0x3e/0x44
>   [<c01cc05f>] ? kmemleak_scan+0x365/0x365
>   [<c01cc0ba>] kmemleak_scan_thread+0x5b/0x98
>   [<c0134119>] kthread+0x76/0x7b
>   [<c01340a3>] ? __init_kthread_worker+0x4a/0x4a
>   [<c047ab46>] kernel_thread_helper+0x6/0x10
> Code: 00 c1 e8 08 33 04 b3 4f 74 05 f6 c2 03 75 e5 89 f9 89 ce c1 e9
> 03 83 e6 07 89 4d ec 8d 4a fc 89 75 f0 89 d6 89 4d e8 31 c9 eb 73<33>
> 04 ce 8b 54 ce 04 89 45 e4 8b 7d e4 25 ff 00 00 00 8b 84 83
> EIP: [<c02f68fe>] crc32_body+0x4e/0xf8 SS:ESP 0068:c4ec7f38
> CR2: 00000000c88f9000
> ---[ end trace 37592748e7ca7ba8 ]---
> BUG: sleeping function called from invalid context at
> /home/jimc/projects/lx/linux-2.6/kernel/rwsem.c:20
> in_atomic(): 1, irqs_disabled(): 1, pid: 31, name: kmemleak
> INFO: lockdep is turned off.
> irq event stamp: 1020924
> hardirqs last  enabled at (1020923): [<c0175fbe>]
> rcu_preempt_note_context_switch+0xaa/0xb0
> hardirqs last disabled at (1020924): [<c0474a95>] _raw_spin_lock_irq+0x15/0x78
> softirqs last  enabled at (1020918): [<c0120d5c>] __do_softirq+0x1b5/0x1fe
> softirqs last disabled at (1020567): [<c01031c7>] do_softirq+0x53/0xa0
> Pid: 31, comm: kmemleak Tainted: G      D    O 3.4.0-rc5-ske+ #64
> Call Trace:
>   [<c013ccea>] __might_sleep+0x178/0x180
>   [<c04736eb>] down_read+0x20/0x7d
>   [<c012a84a>] exit_signals+0x1f/0x10b
>   [<c011ecc5>] do_exit+0xcf/0x327
>   [<c0475f82>] oops_end+0x9f/0xa5
>   [<c0467dc4>] no_context+0x177/0x17f
>   [<c0467f07>] __bad_area_nosemaphore+0x13b/0x143
>   [<c0105d87>] ? native_sched_clock+0x48/0xa2
>   [<c0467f26>] bad_area_nosemaphore+0x17/0x19
>   [<c04776f7>] do_page_fault+0x18f/0x365
>   [<c01571b8>] ? trace_hardirqs_on_caller+0x11/0x145
>   [<c013e077>] ? finish_task_switch.constprop.82+0x6e/0xb1
>   [<c013e036>] ? finish_task_switch.constprop.82+0x2d/0xb1
>   [<c018652f>] ? time_hardirqs_off+0x17/0x28
>   [<c0475906>] ? error_code+0x66/0x70
>   [<c0153d3b>] ? trace_hardirqs_off_caller+0x17/0x8f
>   [<c0477568>] ? spurious_fault+0xb9/0xb9
>   [<c047590a>] error_code+0x6a/0x70
>   [<c02f68fe>] ? crc32_body+0x4e/0xf8
>   [<c02f69e6>] crc32_le+0x12/0x14
>   [<c01cbf39>] kmemleak_scan+0x23f/0x365
>   [<c047336e>] ? mutex_lock_nested+0x3e/0x44
>   [<c01cc05f>] ? kmemleak_scan+0x365/0x365
>   [<c01cc0ba>] kmemleak_scan_thread+0x5b/0x98
>   [<c0134119>] kthread+0x76/0x7b
>   [<c01340a3>] ? __init_kthread_worker+0x4a/0x4a
>   [<c047ab46>] kernel_thread_helper+0x6/0x10
> note: kmemleak[31] exited with preempt_count 1

Jim,

I always build kernels with kmemleak enabled. I have been busy on another 
project and I have not done much testing with acx-mac80211. I will keep my eyes 
open for such problems.

I do have a couple of observations about the kmemleak process. The scans are 
very lengthy, thus the kmemleak process is very likely to show up as the process 
of record whenever any problem happens. It does not mean that kmemleak is the 
problem.

The problem shows up in __sched down_read() at kernel/rwsem.c:20 , thus it 
appears to be semaphore related.

Larry