泰晓科技 -- 聚焦 Linux - 追本溯源，见微知著！
网站地址：https://tinylab.org

还在观望？5小时公开课入门RISC-V架构
请稍侯

bugfix: Qemu 运行 ARM Linux 5.0 必现启动死机

Wu Zhangjin 创作于 2019/05/16
打赏

By Falcon of TinyLab.org May 14, 2019

注：泰晓科技新增 Debugging+Tracing 专辑，全面连载各类 debug 实战技能。本文是该专辑的第一篇，欢迎持续关注。通过该专辑，您可以学习到分析和解决实际问题的方式、方法、工具和技巧。

1 背景介绍

前段时间为 Linux Lab 新增了 5.0.10 for ARM64/virt board，期间遇到了启动死机问题，本文对该问题进行详解。

在继续阅读之前，建议准备好 Linux Lab，方便同时做实验。为复现该问题，请先注释掉 boards/virt/Makefile 中的 QEMU 所在行，或者键入如下命令确保使用旧版本的 qemu。

  1. $ export QEMU=

2 问题现象

编译完 Linux 5.0.10 并通过 Linux Lab 运行时：

  1. $ make BOARD=virt
  2. $ make boot V=1

直接卡死了，只看到 Qemu 的输出日志，没有看到任何内核日志输出 ;-(

3 分析过程

3.1 理清问题基本信息

首先需要承认，面对这种不按套路出牌的 Linux 启动状况（不确定性），这个时候谁都可能“惶恐不安”。接着告诉自己，问题必须解决，冷静！

有两个信息先捋一下：

  • 之前的 Linux v4.5.5 ok，启动完美
  • 网上已经有同学完美启动了 5.0 for ARM64

所以，问题可能原因：

  • Linux v5.0.10 相比 v4.5.5 有变更引入了衰退
  • Linux Lab 所使用的环境跟网上其他同学的环境有差异，可能差异在编译器和 Qemu。

接下来有两个思路：

  • 用二分法找出引入问题的变更，即从 v4.5.5 到 v5.0.10 之间找出第一个启动不了的内核版本
  • 升级 Linux Lab 中的编译器和 Qemu 到最新版本

可是，虽然这两个工作都可行，但还都蛮耗费时间（第2个相对而言没那么耗时），所以，不能逃避，正面扛着看看！

3.2 定下分析方式

ok，先保持内核版本不变、环境不变，正面分析到底 Linux 内核卡死在哪里？！

3.2.1 打开 early Logging 机制

竟然内核什么都没有输出，那么先想办法输出点东西。

死得这么早，可能是普通串口初始化之前就挂了，要在这之前就打印东西，能想到是 early printk：

  1. $ make boot V=1 XKCLI="earlycon"

earlycon 是内核最新的 early printk 逻辑，说明文档在 linux-stable/Documentation/admin-guide/kernel-parameters.txt：

  1. earlycon=  [KNL] Output early console device and options.
  3. [ARM64] The early console is determined by the stdout-path property in device tree's chosen node, or determined by the ACPI SPCR table.
  5. [X86] When used with no options the early console is determined by the ACPI SPCR table.

加上以后，很幸运，有东西咕噜咕噜滚出来了：

  1. $ make boot V=1 XKCLI=earlycon
  2. make  _boot
  3. make[1]: Entering directory `/labs/linux-lab'
  4. sudo qemu-system-aarch64  -M virt -m 128M -net nic,model=virtio -net tap -device virtio-net-device,netdev=net0,mac=c0:2f:fd:e8:dc:ce -netdev tap,id=net0 -smp 2 -cpu cortex-a57 -kernel /labs/linux-lab/output/aarch64/linux-v5.0.10-virt/arch/arm64/boot/Image -no-reboot  -initrd /labs/linux-lab/prebuilt/root/aarch64/cortex-a57/rootfs.cpio.gz -append 'route=172.17.0.5 root=/dev/ram0 earlycon console=ttyAMA0' -nographic
  5. ...
  6. Booting Linux on physical CPU 0x0000000000 [0x411fd070]
  7. Linux version 5.0.10-dirty (ubuntu@5016aaa36868) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05)) #6 SMP Sun May 5 06:42:26 UTC 2019
  8. Machine model: linux,dummy-virt
  9. earlycon: pl11 at MMIO 0x0000000009000000 (options '')
  10. printk: bootconsole [pl11] enabled
  11. ...
  12. ------------[ cut here ]------------
  13. kernel BUG at /labs/linux-lab/linux-stable/arch/arm64/kernel/traps.c:425!
  14. Internal error: Oops - BUG: 0 [#1] SMP
  15. Modules linked in:
  16. Process swapper (pid: 0, stack limit = 0x(____ptrval____))
  17. CPU: 0 PID: 0 Comm: swapper Not tainted 5.0.10-dirty #37
  18. Hardware name: linux,dummy-virt (DT)
  19. pstate: 00000085 (nzcv daIf -PAN -UAO)
  20. pc : do_undefinstr+0x280/0x2c0
  21. lr : do_undefinstr+0x168/0x2c0
  22. ...
  23. Call trace:
  24.  do_undefinstr+0x280/0x2c0
  25.  el1_undef+0x10/0x78
  26.  __cpuinfo_store_cpu+0x80/0x1d0
  27.  cpuinfo_store_boot_cpu+0x28/0x54
  28.  smp_prepare_boot_cpu+0x38/0x40
  29.  start_kernel+0x170/0x450
  30. Code: 2a154035 17ffffb5 a9025bb5 f9001bb7 (d4210000)
  31. ---[ end trace 16cff5c8dd5a6423 ]---
  32. Kernel panic - not syncing: Attempted to kill the idle task!
  33. ---[ end Kernel panic - not syncing: Attempted to kill the idle task! ]---

3.2.2 出错 Log 分析

出错日志有非常关键的 Calltrace 信息，初一看，发现是 undefinstr 异常，并且有触发异常的具体位置：

  1. __cpuinfo_store_cpu+0x80/0x1e4

通过如下命令找到代码所在文件：

  1. $ cd linux-stable
  2. $ grep __cpuinfo_store_cpu -nur arch/arm64/
  3. arch/arm64/kernel/cpuinfo.c:328:static void __cpuinfo_store_cpu(struct cpuinfo_arm64 *info)
  4. arch/arm64/kernel/cpuinfo.c:386:	__cpuinfo_store_cpu(info);
  5. arch/arm64/kernel/cpuinfo.c:393:	__cpuinfo_store_cpu(info);

打开代码初步查看如下：

  1. $ vim arch/arm64/kernel/cpuinfo.c +328
  2. info->reg_cntfrq = arch_timer_get_cntfrq();
  3. ...
  4. info->reg_id_aa64mmfr0 = read_cpuid(ID_AA64MMFR0_EL1);
  5. info->reg_id_aa64mmfr1 = read_cpuid(ID_AA64MMFR1_EL1);
  6. info->reg_id_aa64mmfr2 = read_cpuid(ID_AA64MMFR2_EL1);
  7. info->reg_id_aa64pfr0 = read_cpuid(ID_AA64PFR0_EL1);
  8. info->reg_id_aa64pfr1 = read_cpuid(ID_AA64PFR1_EL1);
  9. info->reg_id_aa64zfr0 = read_cpuid(ID_AA64ZFR0_EL1);

初步猜测，可能是部分寄存器访问出错，但是具体哪一个错了还需要进一步确认。

3.2.3 定位代码出错位置

接下来需要通过 Backtrace 中的 __cpuinfo_store_cpu+0x80 找到准确的出错位置，也就是代码行。

这个寻找过程我们很早有专门的文章介绍，可以查阅：如何快速定位 Linux Panic 出错的代码行。

方法有几种，但是实际发现用 objdump 最为准确，gdb 在这个例子里有一行的偏差。

在这之前，必须确保 vmlinux 是带符号的，否则这些工具没法帮我们定位出错文件和代码行。要让 vmlinux 带符号，必须在 boards/virt/linux_v5.0.10_defconfig 中开启如下配置后重新编译内核：

  1. CONFIG_DEBUG_KERNEL=y
  2. CONFIG_DEBUG_INFO=y
  3. CONFIG_KALLSYMS=y

重新配置和编译内核：

  1. $ make kernel-defconfig
  2. $ make kernel

接下来，回到 Linux Lab 主目录，开始定位问题所在的代码行。先得请 nm 帮找出 __cpuinfo_store_cpu 的地址：

  1. $ aarch64-linux-gnu-nm output/aarch64/linux-v5.0.10-virt/vmlinux | grep __cpuinfo_store_cpu
  2. ffffff80100919c0 t __cpuinfo_store_cpu

同时根据异常日志中的 “__cpuinfo_store_cpu+0x80/0x1d0” 计算出 start-address 和 stop-address，0x80 为出错位置，0x1d0 为函数 size，我们找出这个范围。

  1. $ echo "obase=16;ibase=10;$((0x80100919c0+0x80))" | bc -l
  2. 8010091A40
  3. $ echo "obase=16;ibase=10;$((0x80100919c0+0x1d0))" | bc -l
  4. 8010091B90

接着，请出 objdump 这尊大神，start-address 设置为函数入口，stop-address 设置为

  1. $ aarch64-linux-gnu-objdump -dS output/aarch64/linux-v5.0.10-virt/vmlinux --start-address=0xffffff80100919c0 --stop-address=0xffffff8010091b90
  2. ...
  3.    	info->reg_id_aa64mmfr1 = read_cpuid(ID_AA64MMFR1_EL1);
  4. ffffff8010091a3c:	f901ba60 	str	x0, [x19, #880]
  5. ffffff8010091a40:	d5380740 	mrs	x0, id_aa64mmfr2_el1
  6. info->reg_id_aa64mmfr2 = read_cpuid(ID_AA64MMFR2_EL1);
  7. ffffff8010091a44:	f901be60 	str	x0, [x19, #888]
  8. ffffff8010091a48:	d5380400 	mrs	x0, id_aa64pfr0_el1
  9. info->reg_id_aa64pfr0 = read_cpuid(ID_AA64PFR0_EL1);
  10. ...

找到 “ffffff8010091a40” 所在行：

  1. ffffff8010091a40:	d5380740 	mrs	x0, id_aa64mmfr2_el1
  2. info->reg_id_aa64mmfr2 = read_cpuid(ID_AA64MMFR2_EL1);

3.2.4 分析出错原因

看上去像是该寄存器访问异常。用 vim 打开注释掉该行并重新编译，重新启动，发现继续出错：

  1. Call trace:
  2.  do_undefinstr+0x280/0x2c0
  3.  el1_undef+0x10/0x78
  4.  __cpuinfo_store_cpu+0x90/0x1c8
  5.  cpuinfo_store_boot_cpu+0x28/0x54
  6.  smp_prepare_boot_cpu+0x38/0x40
  7.  start_kernel+0x170/0x450

代码偏移为 0x90，出错位置为：0xffffff8010091b50，同样计算 start-address：0xffffff80100919c0 和 stop-address：0xffffff8010091b88，用 objdump 找到如下位置：

  1. $ aarch64-linux-gnu-objdump -dS output/aarch64/linux-v5.0.10-virt/vmlinux --start-address=0xffffff80100919c0 --stop-address=0xffffff8010091b88
  2. ...
  3. ffffff8010091a48:	d5380422 	mrs	x2, id_aa64pfr1_el1
  4. 	info->reg_id_aa64pfr1 = read_cpuid(ID_AA64PFR1_EL1);
  5. ffffff8010091a4c:	f901c662 	str	x2, [x19, #904]
  6. ffffff8010091a50:	d5380482 	mrs	x2, id_aa64zfr0_el1
  7. 	info->reg_id_aa64zfr0 = read_cpuid(ID_AA64ZFR0_EL1);
  8. ffffff8010091a54:	f901ca62 	str	x2, [x19, #912]

出错位置的代码如下：

  1. ffffff8010091a50:	d5380482 	mrs	x2, id_aa64zfr0_el1
  2. 	info->reg_id_aa64zfr0 = read_cpuid(ID_AA64ZFR0_EL1);

3.2.5 验证解决方法可行性

同样注释掉这部分，重新编译之后就可以正常启动了。需做修改如下：

  1. $ cd linux-stable
  2. $ git diff
  3. -	info->reg_id_aa64mmfr2 = read_cpuid(ID_AA64MMFR2_EL1);
  4. +	//info->reg_id_aa64mmfr2 = read_cpuid(ID_AA64MMFR2_EL1);
  5. ...
  6. -	info->reg_id_aa64zfr0 = read_cpuid(ID_AA64ZFR0_EL1);
  7. +	//info->reg_id_aa64zfr0 = read_cpuid(ID_AA64ZFR0_EL1);

启动日志如下：

  1. ..
  2. Welcome to Linux Lab
  3. linux-lab login: root
  4. #
  5. # uname -a
  6. Linux linux-lab 5.0.10-dirty #39 SMP Sun May 5 13:00:38 UTC 2019 aarch64 GNU/Linux

至此，临时解决方案 ok。已经把上面两笔内核的修改制作成了 patch，并放到了boards/virt/patch/linux/v5.0/ 下，另外，在 boards/virt/Makefile 中配置了 “KP=1”，后续配置时会据此自动打 patch，打上后再编译就可启动了。

3.3 问题复盘

正面分析发现是 Linux 内核代码中有相关寄存器的操作引起了 undefinstr，这部分寄存器官方内核是支持的，说明真实硬件没有问题，所以需要继续看看运行环境部分，也就是这里的 Qemu 模拟器，很大可能是 Qemu 版本问题。

之前 Linux Lab 自带版本是 2.5：

  1. $ qemu-system-aarch64 --version
  2. QEMU emulator version 2.5.0 (Debian 1:2.5+dfsg-5ubuntu4), Copyright (c) 2003-2008 Fabrice Bellard

所以接下来要升级 Qemu 版本，由于未能找到编译好的 Qemu 版本，我们自行编译，并且给 Linux Lab 添加了 Qemu 编译支持，这里不做介绍。

编译完一个新的 v2.12.0 以后测试发现，可以直接正常启动不做改动的 Linux 5.0.10，所以证实了我们的猜测。

  1. $ prebuilt/qemu/aarch64/v2.12.0/bin/qemu-system-aarch64 --version
  2. QEMU emulator version 2.12.0
  3. Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers

4 小结

本文详细介绍了一个典型的 Linux 内核死机问题。在实际产品研发过程中，死机问题会千奇百怪，死机路径可能随机变化，死机概率也因使用环境有高有低，所以，一方面要不断积累解决问题的技术经验，另外一方面尤其重要的是，沉着冷静，在面对类似难题时，坚定解决问题的信心。

欢迎添加作者微信 lzufalcon，进一步交流探讨！


Read Album:

Read Related:

Read Latest: