快速背景:我正在为我们的硬件压缩引擎开发驱动程序。一个驱动程序处理 PCI 交互,每秒处理数千个 32K 数据包。那个司机工作很踏实。现在我正在开发一个字符驱动程序,这看起来很不错,我的测试应用程序正在运行数百个线程而没有问题 - 有一段时间了。然后在 30 分钟或几个小时后,我在 read() 或 write() 中得到了这个“原子调度”BUG - 在 copy_to_user() 或 copy_from_user() 中。如果我持有任何自旋锁,我会知道如何解决这个问题。但我不是。我也不是在中断上下文中。这是来自操作系统的标准 read() 或 write() 路径。
我什至在调用 copy_*_user() 之前检查了 preempt_count(),它每次都显示为零,但是 BUG 说 preempt_count() 在到达 copy_user_generic_string() 时为 0x00000102 或 0x00000100。我知道 0x100 是软中断计数 << 8。但我不确定这是怎么发生的。
我非常仔细地检查了 PCI 驱动程序中的中断和 tasklet 代码。tasklet 确实使用了自旋锁,但代码路径在锁定和解锁之间没有分支点。正如我所说,PCI 驱动程序已经稳定工作了几个月,为我们开发的另一个内核模块提供压缩服务。
这发生在 3.2 内核下的两台不同的机器上:
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
和一个启用了许多调试功能的内核:
Linux drvdev1 3.2.14-altiordbg #1 SMP Fri Apr 27 16:53:48 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux
我打算在 2.6.3 的机器上尝试这个?今天的内核。
这是错误转储。'flex' 是我的多线程测试应用程序。
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