Bug 42775

Created attachment 72387 [details]
Trial patch for kernels 2.6.39 through 3.2

Created attachment 72388 [details]
Trial patch for kernels 3.3 or later

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)

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?

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.

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.

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?

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.

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.

Created attachment 72508 [details]
Revised patch for kernels 2.6.39 through 3.2

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.

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.

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.

Created attachment 72516 [details]
Fix rcu_lock problem for rtl8192cu

Thanks for the explanation. This patch will apply to all kernels.

I currently tested your "Fix rcu_lock problem for rtl8192cu" without the other patch and it seems to work so far.

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

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

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