内核问题解决方法记录

♪

张释文

在内核开发这块，基本工作都是：打补丁，调补丁，调bug。最耗神的就是调bug，调bug的过程最花时间的一步是定位问题，基本上只要定位到问题，解决起来就容易些了(目前我遇到的bug大部分是这样)。所以调试方法很重要，接下来就分享一点如何快速定位并解决bug的一丢丢小经验。抛砖引玉，大佬们见笑。

Contents [hide]

• 1 分析

  • 1.1 根据函数栈定位问题

  • 1.2 根据 modules信息定位问题

• 2 打开对应的debug

• 3 跟进去

分析

根据函数栈定位问题

内核出了bug，首先做的应该是分析这个很重要。如果分析的好，后面可以节省很多时间。根据内核打出的错误日志分析，分析是哪里出了问题。比如说这样的dmesg：

[226041.366182] BUG: unable to handle kernel pointer dereference at 0000000000000050[226041.366336] IP: [] lock_get_status+0xa1/0x340[226041.366492] PGD 2d0d74067 PUD 2d9550067 PMD 0[226041.366649] Oops: 0000 [#1] SMP[226041.366809] Modules linked in: cifs fscache nfnetlink_queue nfnetlink_log nfnetlink bluetooth rfkill xt_limit xt_recent nf_log_ipv4 nf_log_common xt_LOG xt_conntrack xt_nat xt_multiport xt_REDIRECT nf_nat_redirect xt_tcpudp ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_filter ip_tables x_tables pci_stub vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) ipv6 fuse joydev hid_thingm hid_generic uas usb_storage usbhid i2c_dev coretemp hwmon intel_rapl x86_pkg_temp_thermal intel_powerclamp kvm_intel kvm alx irqbypass snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi mxm_wmi evdev crct10dif_pclmul mdio crc32_pclmul crc32c_intel psmouse serio_raw snd_hda_intel battery i915 thermal i2c_hid sdhci_acpi sdhci iosf_mbi drm_kms_helper snd_hda_codec mmc_core dw_dmac fjes elan_i2c drm intel_gtt agpgart i2c_algo_bit fb_sys_fops syscopyarea hid snd_hda_core dw_dmac_core sysfillr[226041.369120] CPU: 0 PID: 28884 Comm: lsof Tainted: G W O 4.4.38 #2[226041.369478] Hardware name: Gigabyte Technology Co., Ltd. Z97X-UD5H/Z97X-UD5H, BIOS F8 06/17/2014[226041.377462] Call Trace:[226041.377973] [] locks_show+0x34/0x70[226041.378495] [] seq_read+0x2b4/0x370[226041.379020] [] proc_reg_read+0x42/0x70[226041.379551] [] __vfs_read+0x28/0xe0[226041.380087] [159e2c0>] ? security_file_permission+0xa0/0xc0[226041.380632] [] ? rw_verify_area+0x4f/0xe0[226041.381182] [] vfs_read+0x86/0x130[226041.381715] [] SyS_read+0x46/0xa0[226041.382228] [] entry_SYSCALL_64_fastpath+0x16/0x6a[226041.383874] RIP [] lock_get_status+0xa1/0x340[226041.384437] RSP dd5bd68>[226041.384996] CR2: 0000000000000050[226041.388290] ---[ end trace b29c72fcb99ad21a ]---

错误日志第一行会说这是个什么错误，比如说访零地址、cpu死锁、计时器超时等等。第二行开始是寄存器内容，硬件信息等。接下来是模块信息，表示发生错误时刻内核中有哪些模块，最后是函数调用栈信息。示例是访零地址错误，这是相对比较容易定位的问题，基本上根据函数栈内容就可以定位到。

根据 modules信息定位问题

之前一直没仔细看过dmesg中打出来的模块信息，直到遇到下面这个问题：

[ 1722.892969] CPU 1 Unable to handle kernel paging request at virtual address 0000000049e50b00, epc == ffffffff803914[ 1722.976089] Oops[#1]:[ 1723.048769] CPU: 1 PID: 5900 Comm: applet.py Tainted: G W O 4.4.32-deepin-loongson-3-generic #1574[ 1723.133560] task: 98000005ff488f70 ti: 98000005fb13c000 task.ti: 98000005fb13c000[ 1724.515206] PrId : 0014630d (Loongson-3)[ 1724.599828] Modules linked in: fuse xfrm_user xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key xfrm_algo cfg80211 rfkilld[ 1724.813071] Process applet.py (pid: 5900, threadinfo=98000005fb13c000, task=98000005ff488f70, tls=000000ffed25f4c0)[ 1725.609798] Call Trace:[ 1725.704123] [] vfs_create+0x4/0x180[ 1725.802203] [] flush_smp_call_function_queue+0xbc/0x1c8[ 1725.902748] [64>] loongson3_ipi_interrupt+0x254/0x280[ 1726.003153] [] mach_irq_dispatch+0x198/0x320[ 1726.103218][ 1726.197324]Code: 080e43ca 2410ffff 000080cd  ffb30018 ffb20010 ffb10008 ffbf0028 ffb00000[ 1726.393771] ---[ end trace 7629c019ddeb2c2f ]---[ 1726.493504] Kernel panic - not syncing: Fatal exception in interrupt[ 1727.446895] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

这是之前的一个panic，这是磊哥调的一个问题。可以看出，函数栈给出的信息不多中断处理->panic，花了两天时间跟进去也没得到太多东西。后来请教磊哥，他说从上面日志的modules信息，能看出来跟文件管理器引起的，才得到了一个突破口。磊哥厉害。

打开对应的debug

内核有时候会报RCU错误，就比如下面这种：

 [ 52.098924] NMI watchdog: BUG: soft lockup - CPU#39 stuck for 22s! [in:imuxsock:1717][ 52.117361] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat joydev sg shpchp sbsa_gwdt ipmi_ssif binfmt_misc ip_tables hid_generic usbhid ses enclosure ohci_pci xhci_pci ohci_hcd ehci_pci xhci_hcd ehci_hcd usbcore hns3 hnae3 usb_common megaraid_sas fjes button[ 52.167146][ 52.179941] CPU: 39 PID: 1717 Comm: in:imuxsock Tainted: G W 4.4.102-deepin-server #700[ 52.200840] Hardware name: Huawei TaiShan 2280 V2/BC82AMDA, BIOS TA BIOS TaiShan 2280 V2 - B900 11/21/2018[ 52.222400] task: ffff802fb5a92a00 ti: ffff802fb52fc000 task.ti: ffff802fb52fc000[ 52.258722] LR is at handle_mm_fault+0x464/0x1128[ 52.275517] pc : [] lr : [] pstate: 60400005[ 85.444259] 39-...: (5959 ticks this GP) idle=c0f/140000000000001/0 softirq=1376/1376 fqs=4280 last_accelerate: 94bc/ac2e, nonlazy_posted: 0, L.[ 85.457822] (t=6002 jiffies g=132 c=131 q=12636)[ 85.462794] Task dump for CPU 39:[ 85.466223] in:imuxsock R running task 0 1717 1 0x00000002[ 85.473538] Call trace:[ 85.476064] [] dump_backtrace+8/0xb4[ 85.504159] [133fa8>] rcu_check_callbacks+0x588/0x888[ 85.510392] [139a9c>] update_process_times+0x3c/0x68[ 85.516538] [1497e4>] tick_sched_handle.isra.6+0x24/0x60[ 85.523042] [149864>] tick_sched_timer+0x44/0x90[ 85.528823] [] __hrtimer_run_queues+0xc4/0x2b0[ 85.535057] [] hrtimer_interrupt+0x94/0x1d0[ 85.541020] [] arch_timer_handler_phys+0x30/0x40[ 85.547434] [] handle_percpu_devid_irq+0x7c/0x170[ 85.553943] [] generic_handle_irq+0x24/0x38[ 85.559905] [] __handle_domain_irq+0x5c/0xb8[ 85.565957] [] gic_handle_irq+0xc4/0x178

这种计时器超时的错误，dmesg信息基本没什么参考性，因为报出这个错误的时候cpu已经hang了22s了，函数栈是跳转之后的，模块信息多且冗杂不能很容易得出结论，这就很头疼。可以用这个方法试试看，运气好的话可以多得到很多有用信息的。打开下面的debug

CONFIG_DEBUG_KERNEL=yCONFIG_DETECT_SOFTLOCKUP=yCONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=0CONFIG_DETECT_HUNG_TASK=yCONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=0CONFIG_SCHED_DEBUG=yCONFIG_DEBUG_PREEMPT=yCONFIG_DEBUG_BUGVERBOSE=yCONFIG_DEBUG_INFO=yCONFIG_DEBUG_RCU

• 在kernel hacking中打开，irq、rcu、lock之类相关的全部开关

运气好的话可以得到更详细的信息，类似于：

[ 40.816000] Badness at drivers/stm/clk.c:190[ 40.816000][ 40.816000] Pid : 779, Comm: reboot[ 40.816000] CPU : 0 Not tainted (2.6.32.59_stm24_0211 #2)[ 40.816000][ 40.816000] PC : 80a8b7e4 SP : 88e59e44 SR : 400080f1 TEA : c16772ac[ 40.816000] R0 : 00000000 R1 : 00000000 R2 : 80c2fe58 R3 : 00002000[ 40.816000] R4 : 80c2fb80 R5 : 80a8b438 R6 : 00000000 R7 : 00003fff[ 40.816000] R8 : 80c2f9a8 R9 : 80a8b426 R10 : 89e2048c R11 : 00000000[ 40.816000] R12 : fffff000 R13 : 80a8b824 R14 : 00000000[ 40.816000] MACH: 000000de MACL: 00000014 GBR : 296c1470 PR : 80a8b810[ 40.816000][ 40.816000] Call trace:[ 40.816000] [<80a8b84a>] 0x80a8b84a[ 40.816000] [<80a58f9e>] 0x80a58f9e[ 40.816000] [<809e055a>] 0x809e055a[ 40.816000] [<8082188c>] 0x8082188c

这个就很有用，内核告诉你具体那个文件哪一行的计时器超时了，这调试起来就很简单了。

跟进去

如果上述方法都不能解决问题，这是最后一个且最麻烦的办法了，跟进去调试。一点一点，要非常有耐心，慢慢分析流程，大胆设想可能出错的位置。秘诀就是：细心、耐心和大胆设想。

比如说之前调的掉盘问题，dmesg打印的信息如下：

[ 4.233517] irq 123, desc: ffff890efa766800, depth: 1, count: 0, unhandled: 0[ 4.233528] ->handle_irq: ffffffffa80e5b60,[ 4.233552] handle_bad_irq+0x0/0x230[ 4.233554] ->irq_data.chip: ffffffffa8f711a0,[ 4.233559] chv_gpio_irqchip+0x0/0x120[ 4.233561] ->action: [ 4.233563] IRQ_NOPROBE set[ 6.547628] ata2.00: qc timeout (cmd 0xec)[ 6.547721] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)[ 7.007213] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)[ 16.997819] ata2.00: qc timeout (cmd 0xec)[ 16.997910] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)

多次重启测试后，基本上能确定在123号中断出现以后，盘就掉了。系统hang住。怀疑是ata驱动的问题。bad irq问题是最难确定的一种问题，因为中断是硬件产生的，没办法看到

产生的过程，所以只能愚蠢的一点一点扣代码，一点点猜，这需要耐心。大概猜了200+次以后，才能基本确定跟ata驱动没关系(因为可能的地方都查看过了，没问题)。

问题是由异常中断引起的，既然不是驱动的问题，那就是中断处理的问题咯。这是一个大胆的猜想，因为所有的中断工作都是ok的，只是这一个。后面调试还真是中断处理流的问题。orz….其实只要细心一点。应该不用尝试200+次后，定位出来的。

这就是我分享的这个季度用到的定位方法，比较粗糙。各位大神们还有什么好用的办法，求教。