内核问题解决方法记录

刘盼

发布于 2019-08-06 14:55:04

2.2K0

发布于 2019-08-06 14:55:04

内核问题解决方法记录

在内核开发这块，基本工作都是：打补丁，调补丁，调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 NULL pointer dereference at 0000000000000050
[226041.366336] IP: [<ffffffff812102f1>] 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]  [<ffffffff81210674>] locks_show+0x34/0x70
[226041.378495]  [<ffffffff811e4414>] seq_read+0x2b4/0x370
[226041.379020]  [<ffffffff8122a442>] proc_reg_read+0x42/0x70
[226041.379551]  [<ffffffff811c15f8>] __vfs_read+0x28/0xe0
[226041.380087]  [<ffffffff8159e2c0>] ? security_file_permission+0xa0/0xc0
[226041.380632]  [<ffffffff811c1edf>] ? rw_verify_area+0x4f/0xe0
[226041.381182]  [<ffffffff811c1ff6>] vfs_read+0x86/0x130
[226041.381715]  [<ffffffff811c2ca6>] SyS_read+0x46/0xa0
[226041.382228]  [<ffffffff81c7119b>] entry_SYSCALL_64_fastpath+0x16/0x6a
[226041.383874] RIP  [<ffffffff812102f1>] lock_get_status+0xa1/0x340
[226041.384437]  RSP <ffff88012dd5bd68>[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] [<ffffffff80391094>] vfs_create+0x4/0x180[ 1725.802203] [<ffffffff802bdb34>] flush_smp_call_function_queue+0xbc/0x1c8[ 1725.902748] [<ffffffff80207c64>] loongson3_ipi_interrupt+0x254/0x280[ 1726.003153] [<ffffffff80202be0>] mach_irq_dispatch+0x198/0x320[ 1726.103218]
[ 1726.197324]
Code: 080e43ca  2410ffff  000080cd <ffb40020> 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 : [<ffff0000081f2294>] lr : [<ffff0000081f1a1c>] 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] [<ffff000008089a40>] dump_backtrace+8/0xb4
    [   85.504159] [<ffff000008133fa8>] rcu_check_callbacks+0x588/0x888
    [   85.510392] [<ffff000008139a9c>] update_process_times+0x3c/0x68
    [   85.516538] [<ffff0000081497e4>] tick_sched_handle.isra.6+0x24/0x60
    [   85.523042] [<ffff000008149864>] tick_sched_timer+0x44/0x90
    [   85.528823] [<ffff00000813a2fc>] __hrtimer_run_queues+0xc4/0x2b0
    [   85.535057] [<ffff00000813ab84>] hrtimer_interrupt+0x94/0x1d0
    [   85.541020] [<ffff0000086fcdf8>] arch_timer_handler_phys+0x30/0x40
    [   85.547434] [<ffff00000812313c>] handle_percpu_devid_irq+0x7c/0x170
    [   85.553943] [<ffff00000811e5e4>] generic_handle_irq+0x24/0x38
    [   85.559905] [<ffff00000811e934>] __handle_domain_irq+0x5c/0xb8
    [   85.565957] [<ffff0000080818e4>] gic_handle_irq+0xc4/0x178

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

CONFIG_DEBUG_KERNEL=y
CONFIG_DETECT_SOFTLOCKUP=y
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=0
CONFIG_DETECT_HUNG_TASK=y
CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=0
CONFIG_SCHED_DEBUG=y
CONFIG_DEBUG_PREEMPT=y
CONFIG_DEBUG_BUGVERBOSE=y
CONFIG_DEBUG_INFO=y
CONFIG_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(): (null)
[   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+次后，定位出来的。

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

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2019-08-04，如有侵权请联系 cloudcommunity@tencent.com 删除

编程算法

本文分享自人人都是极客微信公众号，前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与腾讯云自媒体分享计划，欢迎热爱写作的你一起参与！

编程算法

登录后参与评论

0 条评论

热度