Driver - "Scheduling while atomic" in copy_to/from_user(), but not holding any locks

Quick background: I'm developing drivers for our hardware compression engine. One driver handles the PCI interactions, many thousands of 32K packets per second. That driver is working solidly. Now I'm working on a character driver and that's looking pretty good, my test app is running hundreds of threads without issues - for a while. Then after 30 minutes or maybe a few hours, I get this "scheduling while atomic" BUG in read() or write() - in copy_to_user() or copy_from_user(). If I were holding any spinlocks, I'd know how to fix the problem. But I'm not. Nor am I in interrupt context. This is the standard read() or write() path from the OS.

I even checked preempt_count() just before calling copy_*_user() and it showed zero every time, yet the BUG says that preempt_count() is 0x00000102 or 0x00000100 when it reaches copy_user_generic_string(). I know the 0x100 is the softirq count << 8. But I'm not sure how that's happening.

I went over my interrupt and tasklet code in the PCI driver very carefully. The tasklet does use a spinlock but the code path has no branch points between the lock and unlock. And as I said, the PCI driver has been working solidly for months, providing compression services to another kernel module we developed.

This is happening on two different machines under the 3.2 kernel:

Linux driver2 3.2.0-23-generic #36-Ubuntu SMP Tue Apr 10 20:39:51 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

and a kernel built with a lot of debug features enabled:

Linux drvdev1 3.2.14-altiordbg #1 SMP Fri Apr 27 16:53:48 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux

I plan on trying this on a machine with a 2.6.3? kernel today.

Here's the bug dump. 'flex' is my multi-threaded test app.

Jun 20 17:18:21 drvdev1 kernel: [  617.223048] BUG: scheduling while atomic: flex/11476/0x00000102
Jun 20 17:18:21 drvdev1 kernel: [  617.223144] no locks held by flex/11476.
Jun 20 17:18:21 drvdev1 kernel: [  617.223147] Modules linked in: altra_gzip(O) altra_pci(O) altraflex(O) snd_hda_codec_hdmi ppdev sp5100_tco psmouse serio_raw k10temp edac_core edac_mce_amd snd_hda_codec_via i2c_piix4 joydev snd_hda_intel radeon snd_hda_codec snd_hwdep snd_pcm ttm drm_kms_helper drm snd_timer snd soundcore i2c_algo_bit snd_page_alloc shpchp parport_pc asus_atk0110 mac_hid wmi lp parport firewire_ohci firewire_core crc_itu_t pata_atiixp r8169 hid_ezkey usbhid hid
Jun 20 17:18:21 drvdev1 kernel: [  617.223200] CPU 0 
Jun 20 17:18:21 drvdev1 kernel: [  617.223202] Modules linked in: altra_gzip(O) altra_pci(O) altraflex(O) snd_hda_codec_hdmi ppdev sp5100_tco psmouse serio_raw k10temp edac_core edac_mce_amd snd_hda_codec_via i2c_piix4 joydev snd_hda_intel radeon snd_hda_codec snd_hwdep snd_pcm ttm drm_kms_helper drm snd_timer snd soundcore i2c_algo_bit snd_page_alloc shpchp parport_pc asus_atk0110 mac_hid wmi lp parport firewire_ohci firewire_core crc_itu_t pata_atiixp r8169 hid_ezkey usbhid hid
Jun 20 17:18:21 drvdev1 kernel: [  617.223243] 
Jun 20 17:18:21 drvdev1 kernel: [  617.223247] Pid: 11476, comm: flex Tainted: G           O 3.2.14-altiordbg #1 System manufacturer System Product Name/M4A785TD-V EVO
Jun 20 17:18:21 drvdev1 kernel: [  617.223256] RIP: 0010:[<ffffffff813397bd>]  [<ffffffff813397bd>] copy_user_generic_string+0x2d/0x40
Jun 20 17:18:21 drvdev1 kernel: [  617.223269] RSP: 0018:ffff8801d1ecde20  EFLAGS: 00000246
Jun 20 17:18:21 drvdev1 kernel: [  617.223272] RAX: ffff8801d1ecc000 RBX: 0000000000000246 RCX: 0000000000000fa9
Jun 20 17:18:21 drvdev1 kernel: [  617.223275] RDX: 0000000000000000 RSI: 00007ffa86fd12c8 RDI: ffff8801e7f802b8
Jun 20 17:18:21 drvdev1 kernel: [  617.223280] RBP: ffff8801d1ecde88 R08: 0000000000000001 R09: 0000000000000000
Jun 20 17:18:21 drvdev1 kernel: [  617.223283] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
Jun 20 17:18:21 drvdev1 kernel: [  617.223287] R13: 0000000000000246 R14: ffff8801da980000 R15: ffffffff8114b01c
Jun 20 17:18:21 drvdev1 kernel: [  617.223290] FS:  00007ffa7a797700(0000) GS:ffff880216e00000(0000) knlGS:0000000000000000
Jun 20 17:18:21 drvdev1 kernel: [  617.223297] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 20 17:18:21 drvdev1 kernel: [  617.223300] CR2: 0000000000aea000 CR3: 00000001d1da7000 CR4: 00000000000006f0
Jun 20 17:18:21 drvdev1 kernel: [  617.223305] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun 20 17:18:21 drvdev1 kernel: [  617.223310] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Jun 20 17:18:21 drvdev1 kernel: [  617.223314] Process flex (pid: 11476, threadinfo ffff8801d1ecc000, task ffff8801da980000)
Jun 20 17:18:21 drvdev1 kernel: [  617.223318] Stack:
Jun 20 17:18:21 drvdev1 kernel: [  617.223348]  ffffffffa02bace8 ffff8801d1ecde48 ffffffff81096da8 ffff8801d1ecde48
Jun 20 17:18:21 drvdev1 kernel: [  617.223355]  ffffffff810a424d ffff8801e7f80000 00007ffa86fd1010 ffffffff81c2bc80
Jun 20 17:18:21 drvdev1 kernel: [  617.223362]  ffff8801dae60000 000000000000ffff ffff8801dae600f0 ffff8801d3a17c80
Jun 20 17:18:21 drvdev1 kernel: [  617.223368] Call Trace:
Jun 20 17:18:21 drvdev1 kernel: [  617.223407]  [<ffffffffa02bace8>] ? accumulate_from+0x98/0x1f0 [altra_gzip]
Jun 20 17:18:21 drvdev1 kernel: [  617.223414]  [<ffffffff81096da8>] ? sched_clock_cpu+0xa8/0x110
Jun 20 17:18:21 drvdev1 kernel: [  617.223420]  [<ffffffff810a424d>] ? trace_hardirqs_off+0xd/0x10
Jun 20 17:18:21 drvdev1 kernel: [  617.223425]  [<ffffffffa02bbec1>] _write+0xf1/0x3e0 [altra_gzip]
Jun 20 17:18:21 drvdev1 kernel: [  617.223432]  [<ffffffff812bb95c>] ? security_file_permission+0x2c/0xb0
Jun 20 17:18:21 drvdev1 kernel: [  617.223437]  [<ffffffff8118c006>] vfs_write+0xb6/0x180
Jun 20 17:18:21 drvdev1 kernel: [  617.223441]  [<ffffffff8118c32d>] sys_write+0x4d/0x90
Jun 20 17:18:21 drvdev1 kernel: [  617.223448]  [<ffffffff8168b482>] system_call_fastpath+0x16/0x1b
Jun 20 17:18:21 drvdev1 kernel: [  617.223452] Code: 74 30 83 fa 08 72 27 89 f9 83 e1 07 74 15 83 e9 08 f7 d9 29 ca 8a 06 88 07 48 ff c6 48 ff c7 ff c9 75 f2 89 d1 c1 e9 03 83 e2 07 <f3> 48 a5 89 d1 f3 a4 31 c0 c3 66 0f 1f 84 00 00 00 00 00 21 d2 
Jun 20 17:18:21 drvdev1 kernel: [  617.223979] Call Trace:
Jun 20 17:18:21 drvdev1 kernel: [  617.223983]  [<ffffffffa02bace8>] ? accumulate_from+0x98/0x1f0 [altra_gzip]
Jun 20 17:18:21 drvdev1 kernel: [  617.223989]  [<ffffffff81096da8>] ? sched_clock_cpu+0xa8/0x110
Jun 20 17:18:21 drvdev1 kernel: [  617.223994]  [<ffffffff810a424d>] ? trace_hardirqs_off+0xd/0x10
Jun 20 17:18:21 drvdev1 kernel: [  617.223999]  [<ffffffffa02bbec1>] _write+0xf1/0x3e0 [altra_gzip]
Jun 20 17:18:21 drvdev1 kernel: [  617.224043]  [<ffffffff812bb95c>] ? security_file_permission+0x2c/0xb0
Jun 20 17:18:21 drvdev1 kernel: [  617.224051]  [<ffffffff8118c006>] vfs_write+0xb6/0x180
Jun 20 17:18:21 drvdev1 kernel: [  617.224058]  [<ffffffff8118c32d>] sys_write+0x4d/0x90
Jun 20 17:18:21 drvdev1 kernel: [  617.224065]  [<ffffffff8168b482>] system_call_fastpath+0x16/0x1b