Bug 42775

Summary: rtl8192cu: sleeping function called from invalid context
Product: Drivers Reporter: Ronald Wahl (ronald.wahl)
Component: network-wirelessAssignee: Larry Finger (Larry.Finger)
Status: CLOSED CODE_FIX    
Severity: normal CC: florian, Larry.Finger, linville
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.2.5 Subsystem:
Regression: No Bisected commit-id:
Attachments: Trial patch for kernels 2.6.39 through 3.2
Trial patch for kernels 3.3 or later
Revised patch for kernels 3.3+
Revised patch for kernels 2.6.39 through 3.2
Fix rcu_lock problem for rtl8192cu

Description Ronald Wahl 2012-02-15 16:12:41 UTC
There are some issues when using the rtl8192cu wireless driver in kernel 3.2.5: Especially when loading with parameter debug=4 I get some traces about sleeping function called from invalid context:

(1) This one is because the rcu_read_lock is held in rtl92c_dm_refresh_rate_adaptive_mask() and can be fixed locally in the driver

BUG: sleeping function called from invalid context at mm/slub.c:935
in_atomic(): 1, irqs_disabled(): 0, pid: 128, name: kworker/0:1
[<c000e158>] (unwind_backtrace+0x0/0x12c) from [<c02db684>] (dump_stack+0x20/0x24)
[<c02db684>] (dump_stack+0x20/0x24) from [<c0017238>] (__might_sleep+0x104/0x124)
[<c0017238>] (__might_sleep+0x104/0x124) from [<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0)
[<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0) from [<bf20b398>] (_usb_read_sync+0x40/0xd0 [rtlwifi])
[<bf20b398>] (_usb_read_sync+0x40/0xd0 [rtlwifi]) from [<bf20b44c>] (_usb_read32_sync+0x24/0x28 [rtlwifi])
[<bf20b44c>] (_usb_read32_sync+0x24/0x28 [rtlwifi]) from [<bf2a0be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu])
[<bf2a0be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu]) from [<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common])
[<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common]) from [<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi])
[<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi]) from [<c00398c4>] (process_one_work+0x294/0x474)
[<c00398c4>] (process_one_work+0x294/0x474) from [<c003c0a8>] (worker_thread+0x214/0x344)
[<c003c0a8>] (worker_thread+0x214/0x344) from [<c0040330>] (kthread+0x94/0x9c)
[<c0040330>] (kthread+0x94/0x9c) from [<c0009eec>] (kernel_thread_exit+0x0/0x8)

(2) This one is because a lock is held in the mac80211 layer

BUG: sleeping function called from invalid context at mm/slub.c:935
in_atomic(): 1, irqs_disabled(): 0, pid: 11580, name: kworker/u:2
[<c000e158>] (unwind_backtrace+0x0/0x12c) from [<c02db684>] (dump_stack+0x20/0x24)
[<c02db684>] (dump_stack+0x20/0x24) from [<c0017238>] (__might_sleep+0x104/0x124)
[<c0017238>] (__might_sleep+0x104/0x124) from [<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0)
[<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0) from [<bf459398>] (_usb_read_sync+0x40/0xd0 [rtlwifi])
[<bf459398>] (_usb_read_sync+0x40/0xd0 [rtlwifi]) from [<bf45944c>] (_usb_read32_sync+0x24/0x28 [rtlwifi])
[<bf45944c>] (_usb_read32_sync+0x24/0x28 [rtlwifi]) from [<bf486c04>] (rtl92cu_update_hal_rate_table+0x1e8/0x24c [rtl8192cu])
[<bf486c04>] (rtl92cu_update_hal_rate_table+0x1e8/0x24c [rtl8192cu]) from [<bf451830>] (rtl_op_sta_add+0x114/0x13c [rtlwifi])
[<bf451830>] (rtl_op_sta_add+0x114/0x13c [rtlwifi]) from [<bf0bd4d0>] (sta_info_finish_insert+0x80/0x204 [mac80211])
[<bf0bd4d0>] (sta_info_finish_insert+0x80/0x204 [mac80211]) from [<bf0bdb18>] (sta_info_insert_non_ibss+0x108/0x140 [mac80211])
[<bf0bdb18>] (sta_info_insert_non_ibss+0x108/0x140 [mac80211]) from [<bf0bdfc0>] (sta_info_reinsert+0x4c/0x78 [mac80211])
[<bf0bdfc0>] (sta_info_reinsert+0x4c/0x78 [mac80211]) from [<bf0c7d4c>] (ieee80211_assoc_success+0x474/0x7c0 [mac80211])
[<bf0c7d4c>] (ieee80211_assoc_success+0x474/0x7c0 [mac80211]) from [<bf0c81c0>] (ieee80211_assoc_done+0x128/0x1e4 [mac80211])
[<bf0c81c0>] (ieee80211_assoc_done+0x128/0x1e4 [mac80211]) from [<bf0c98a8>] (ieee80211_work_work+0x2c0/0x11c0 [mac80211])
[<bf0c98a8>] (ieee80211_work_work+0x2c0/0x11c0 [mac80211]) from [<c00398c4>] (process_one_work+0x294/0x474)
[<c00398c4>] (process_one_work+0x294/0x474) from [<c003c0a8>] (worker_thread+0x214/0x344)
[<c003c0a8>] (worker_thread+0x214/0x344) from [<c0040330>] (kthread+0x94/0x9c)
[<c0040330>] (kthread+0x94/0x9c) from [<c0009eec>] (kernel_thread_exit+0x0/0x8)

I can't tell if these are regressions since I just started to test the driver with that kernel.
Comment 1 Larry Finger 2012-02-15 18:39:46 UTC
Created attachment 72387 [details]
Trial patch for kernels 2.6.39 through 3.2
Comment 2 Larry Finger 2012-02-15 18:41:04 UTC
Created attachment 72388 [details]
Trial patch for kernels 3.3 or later
Comment 3 Ronald Wahl 2012-02-27 10:53:07 UTC
I tried the patch for 3.2 and it breaks the driver. Maybe the _usb_read_sync function is called concurrently!? When putting the u32 data field on the stack the driver starts working again.

But anyway - there is still a sleeping in atomic issue because of the synchronous USB transfer. This will call kmalloc with GFP_KERNEL by itself and additionally it will sleep internally until the request is done. Both is not suitable for atomic context.

BUG: sleeping function called from invalid context at mm/slub.c:935
in_atomic(): 1, irqs_disabled(): 0, pid: 284, name: kworker/0:2
[<c000e158>] (unwind_backtrace+0x0/0x12c) from [<c02db684>] (dump_stack+0x20/0x24)
[<c02db684>] (dump_stack+0x20/0x24) from [<c0017238>] (__might_sleep+0x104/0x124)
[<c0017238>] (__might_sleep+0x104/0x124) from [<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0)
[<c00b123c>] (kmem_cache_alloc_trace+0x4c/0x1f0) from [<c01e597c>] (usb_control_msg+0x50/0x108)
[<c01e597c>] (usb_control_msg+0x50/0x108) from [<bf20beac>] (_usb_read_sync.clone.20+0x5c/0x84 [rtlwifi])
[<bf20beac>] (_usb_read_sync.clone.20+0x5c/0x84 [rtlwifi]) from [<bf20bef4>] (_usb_read32_sync+0x20/0x24 [rtlwifi])
[<bf20bef4>] (_usb_read32_sync+0x20/0x24 [rtlwifi]) from [<bf265be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu])
[<bf265be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu]) from [<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common])
[<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common]) from [<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi])
[<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi]) from [<c00398c4>] (process_one_work+0x294/0x474)
[<c00398c4>] (process_one_work+0x294/0x474) from [<c003c0a8>] (worker_thread+0x214/0x344)
[<c003c0a8>] (worker_thread+0x214/0x344) from [<c0040330>] (kthread+0x94/0x9c)
[<c0040330>] (kthread+0x94/0x9c) from [<c0009eec>] (kernel_thread_exit+0x0/0x8)
BUG: scheduling while atomic: kworker/0:2/284/0x00000002
Modules linked in: rtl8192cu aes_generic arc4 rtl8192c_common rtlwifi rt2800usb rt2800lib crc_ccitt rt2x00usb rt2x00lib ath9k_htc ath9k_common ath9k_hw carl9170 mac80211 firmware_class ath cfg80211 g_serial v4l2_int_device uvcvideo v4l2_common videodev [last unloaded: rtl8192cu]
[<c000e158>] (unwind_backtrace+0x0/0x12c) from [<c02db684>] (dump_stack+0x20/0x24)
[<c02db684>] (dump_stack+0x20/0x24) from [<c0017770>] (__schedule_bug+0x70/0x7c)
[<c0017770>] (__schedule_bug+0x70/0x7c) from [<c02dbe40>] (__schedule+0x68/0x548)
[<c02dbe40>] (__schedule+0x68/0x548) from [<c02dc454>] (schedule+0x80/0x84)
[<c02dc454>] (schedule+0x80/0x84) from [<c02dc76c>] (schedule_timeout+0x28/0x2d4)
[<c02dc76c>] (schedule_timeout+0x28/0x2d4) from [<c02dbc2c>] (wait_for_common+0x110/0x1e0)
[<c02dbc2c>] (wait_for_common+0x110/0x1e0) from [<c02dbdb0>] (wait_for_completion_timeout+0x1c/0x20)
[<c02dbdb0>] (wait_for_completion_timeout+0x1c/0x20) from [<c01e5738>] (usb_start_wait_urb+0x78/0x13c)
[<c01e5738>] (usb_start_wait_urb+0x78/0x13c) from [<c01e5a08>] (usb_control_msg+0xdc/0x108)
[<c01e5a08>] (usb_control_msg+0xdc/0x108) from [<bf20beac>] (_usb_read_sync.clone.20+0x5c/0x84 [rtlwifi])
[<bf20beac>] (_usb_read_sync.clone.20+0x5c/0x84 [rtlwifi]) from [<bf20bef4>] (_usb_read32_sync+0x20/0x24 [rtlwifi])
[<bf20bef4>] (_usb_read32_sync+0x20/0x24 [rtlwifi]) from [<bf265be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu])
[<bf265be4>] (rtl92cu_update_hal_rate_table+0x1c8/0x210 [rtl8192cu]) from [<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common])
[<bf21e950>] (rtl92c_dm_watchdog+0x10ec/0x1390 [rtl8192c_common]) from [<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi])
[<bf200484>] (rtl_watchdog_wq_callback+0x2ec/0x320 [rtlwifi]) from [<c00398c4>] (process_one_work+0x294/0x474)
[<c00398c4>] (process_one_work+0x294/0x474) from [<c003c0a8>] (worker_thread+0x214/0x344)
[<c003c0a8>] (worker_thread+0x214/0x344) from [<c0040330>] (kthread+0x94/0x9c)
[<c0040330>] (kthread+0x94/0x9c) from [<c0009eec>] (kernel_thread_exit+0x0/0x8)
Comment 4 Larry Finger 2012-02-27 16:21:25 UTC
The u32 buffer was originally on the stack, but that generates a different warning.

I think the fix for both issues will be to establish a ring pool of buffers that are preallocated and available when needed.

I still wonder why you see all these issues when I do not. Is there something special about your hardware?
Comment 5 Ronald Wahl 2012-02-27 16:41:02 UTC
My hardware is an AT91SAM9G20 (ARM926EJ-S) which is a lot slower in respect to regular PC hardware and has only full speed USB. Additionally I have some warnings like CONFIG_DEBUG_ATOMIC_SLEEP enabled. It seems to make a difference as well if the driver is loaded with debug=4, e.g. modprobe -v rtl8192cu debug=4. Doing this the chance triggering the issue is higher. Probably because logging on the serial console (@115200bps) changes the timing.
Comment 6 Larry Finger 2012-02-27 22:01:21 UTC
It turned out that I did not have CONFIG_DEBUG_ATOMIC_SLEEP enabled. I thought I had every reasonable test enabled, but I missed that one.
Comment 7 Larry Finger 2012-02-29 04:57:59 UTC
Funny, even when I enabled CONFIG_DEBUG_ATOMIC_SLEEP, I still did not get the warning that you see; however, when I put the buffer on the stack, my old warning returned:

[ 3840.366271] ------------[ cut here ]------------
[ 3840.366283] WARNING: at lib/dma-debug.c:930 check_for_stack+0xb1/0xf0()
[ 3840.366287] Hardware name: HP Pavilion dv2700 Notebook PC
[ 3840.366293] ehci_hcd 0000:00:02.1: DMA-API: device driver maps memory fromstack [addr=ffff8800af4cfc84]
[ 3840.366298] Modules linked in: rtl8192cu(+) rtl8192ce rtl8192c_common rtlwifi mac80211 cfg80211 rfkill fuse aes_x86_64 aes_generic nfs nfsd lockd auth_rpcgss nfs_acl sunrpc exportfs af_packet cpufreq_conservative cpufreq_userspace cpufreq_powersave powernow_k8 mperf ext3 jbd ide_cd_mod cdrom snd_hda_codec_conexant ide_pci_generic arc4 snd_hda_intel snd_hda_codec snd_pcm snd_timer snd soundcore amd74xx i2c_nforce2 k8temp ide_core i2c_core ac forcedeth hwmon snd_page_alloc joydev video sg serio_raw battery button ipv6 autofs4 ext4 mbcache jbd2 crc16 sd_mod ohci_hcd ehci_hcd ahci libahci libata scsi_mod usbcore usb_common fan processor thermal [last unloaded: rfkill]
[ 3840.366417] Pid: 13523, comm: modprobe Not tainted 3.3.0-rc5-wl+ #205
[ 3840.366421] Call Trace:
[ 3840.366429]  [<ffffffff8103645a>] warn_slowpath_common+0x7a/0xb0
[ 3840.366436]  [<ffffffff81036531>] warn_slowpath_fmt+0x41/0x50
[ 3840.366447]  [<ffffffff812073a1>] check_for_stack+0xb1/0xf0
[ 3840.366453]  [<ffffffff8120760d>] debug_dma_map_page+0xed/0x140
[ 3840.366483]  [<ffffffffa0024edc>] usb_hcd_map_urb_for_dma+0x4ec/0x570 [usbcore]
[ 3840.366506]  [<ffffffffa00256d5>] usb_hcd_submit_urb+0x105/0x6b0 [usbcore]
[ 3840.366534]  [<ffffffffa00266fc>] usb_submit_urb+0xec/0x300 [usbcore]
[ 3840.366552]  [<ffffffffa0027baf>] usb_start_wait_urb+0x6f/0x100 [usbcore]
[ 3840.366580]  [<ffffffffa0027eb1>] usb_control_msg+0xe1/0x120 [usbcore]
[ 3840.366596]  [<ffffffffa07e4f2d>] _usb_read_sync.isra.20+0x7d/0xd0 [rtlwifi]
[ 3840.366606]  [<ffffffffa07e4f95>] _usb_read32_sync+0x15/0x20 [rtlwifi]
[ 3840.366619]  [<ffffffffa080c41c>] rtl92c_read_chip_version+0x1c/0x360 [rtl8192cu]
[ 3840.366630]  [<ffffffffa07e6b5c>] rtl_usb_probe+0x1a3/0x6b1 [rtlwifi]
[ 3840.366648]  [<ffffffffa002a227>] ? usb_match_one_id+0x37/0xc0 [usbcore]
[ 3840.366668]  [<ffffffffa002a505>] usb_probe_interface+0xb5/0x160 [usbcore]
[ 3840.366676]  [<ffffffff8129cb53>] driver_probe_device+0x73/0x190
[ 3840.366684]  [<ffffffff8129cd13>] __driver_attach+0xa3/0xb0
[ 3840.366690]  [<ffffffff8129cc70>] ? driver_probe_device+0x190/0x190
[ 3840.366697]  [<ffffffff8129b1a6>] bus_for_each_dev+0x56/0x90
[ 3840.366708]  [<ffffffff8129c819>] driver_attach+0x19/0x20
[ 3840.366715]  [<ffffffff8129c4a0>] bus_add_driver+0x1b0/0x280
[ 3840.366722]  [<ffffffff8129d251>] driver_register+0x71/0x140
[ 3840.366729]  [<ffffffff811fcbe8>] ? __raw_spin_lock_init+0x38/0x60
[ 3840.366748]  [<ffffffffa0029b70>] usb_register_driver+0xc0/0x1b0 [usbcore]
[ 3840.366756]  [<ffffffffa036d000>] ? 0xffffffffa036cfff
[ 3840.366766]  [<ffffffffa036d01e>] rtl8192cu_driver_init+0x1e/0x20 [rtl8192cu]
[ 3840.366774]  [<ffffffff810001ca>] do_one_initcall+0x3a/0x170
[ 3840.366782]  [<ffffffff810a262a>] sys_init_module+0x8a/0x200
[ 3840.366790]  [<ffffffff81391fa2>] system_call_fastpath+0x16/0x1b
[ 3840.366795] ---[ end trace a4dbeb917e99e92d ]---

Does your device only do PIO on the USB ports?
Comment 8 Ronald Wahl 2012-02-29 09:51:39 UTC
Each of us has his set of disabled debug options - in my case CONFIG_DMA_API_DEBUG was not set. Mea culpa. ;-)
And in general it makes sense to not using stack memory for DMA because normally the DMA is executed while normal code proceeds.

The sleeping while atomic traces I see when I use the debug=4 module option which generates debug output on the console. Since my device is a lot slower than a normal PC and the debug output is placed on a serial device that is not using DMA it may trigger issues not seen on other faster hardware.
Comment 9 Larry Finger 2012-03-01 16:08:59 UTC
Created attachment 72507 [details]
Revised patch for kernels 3.3+

This version implements the read buffer in a ring that is 100 entries. On my system, that covers more than enough concurrent requests.
Comment 10 Larry Finger 2012-03-01 16:17:25 UTC
Created attachment 72508 [details]
Revised patch for kernels 2.6.39 through 3.2
Comment 11 Ronald Wahl 2012-03-01 16:29:20 UTC
I'll check the updated patch soon but while this fixes one reason for sleeping while atomic it does not yet fix the synchronous USB access operation the lock. This synchronous USB read operation  calls non-atomic kmalloc() by itself and waits for USB completion that may sleep as well. See also comment #3.
Comment 12 Larry Finger 2012-03-01 17:55:46 UTC
I'm confused about that one. As rtl92cu_update_hal_rate_table is called from a work queue callback, why is it atomic?

Of course, the trivial fix would be to delete the RT_TRACE statement, or modify it to not do a read there.
Comment 13 Ronald Wahl 2012-03-02 10:46:59 UTC
It is atomic because the rcu_lock is held. This lock is an "atomic lock" and you are not allowed to sleep while holding it.
Comment 14 Larry Finger 2012-03-02 16:54:23 UTC
Created attachment 72516 [details]
Fix rcu_lock problem for rtl8192cu

Thanks for the explanation. This patch will apply to all kernels.
Comment 15 Ronald Wahl 2012-03-02 17:34:53 UTC
I currently tested your "Fix rcu_lock problem for rtl8192cu" without the other patch and it seems to work so far.
Comment 16 Florian Mickler 2012-04-04 15:01:19 UTC
A patch referencing this bug report has been merged in Linux v3.4-rc1:

commit ebecdcc12fed5d3c81853dea61a0a78a5aefab52
Author: Larry Finger <Larry.Finger@lwfinger.net>
Date:   Fri Mar 2 15:23:36 2012 -0600

    rtlwifi: rtl8192c: Prevent sleeping from invalid context in rtl8192cu
Comment 17 Florian Mickler 2012-04-16 21:19:43 UTC
A patch referencing this bug report has been merged in Linux v3.4-rc3:

commit a7959c1394d4126a70a53b914ce4105f5173d0aa
Author: Larry Finger <Larry.Finger@lwfinger.net>
Date:   Mon Mar 19 15:44:31 2012 -0500

    rtlwifi: Preallocate USB read buffers and eliminate kalloc in read routine
Comment 18 Florian Mickler 2012-07-01 09:45:24 UTC
A patch referencing this bug report has been merged in Linux v3.5-rc1:

commit 30899cc6ab4d4b63d43f6d652d1ecf9107eadb8d
Author: Larry Finger <Larry.Finger@lwfinger.net>
Date:   Mon Mar 19 15:44:31 2012 -0500

    rtlwifi: Preallocate USB read buffers and eliminate kalloc in read routine