捉虫日记 0007: Cache aliases issue (1)

1 Phenomenon

BCM56218 (BCM3302 MIPS core, 32KB 2-way DCache) SoC，Glibc_small rootfs on MTD，启动后，在最后运行 busybox 时，内核总会输出 "Segmentation fault" or "Bus error"：

.............
rting pid 590, console /dev/console: '/etc/init.d/rcS'
Bus error
Segmentation fault

Welcome to Wind River Linux
Please press Enter to activate this console.
Starting pid 595, console /dev/console: '/bin/sh'
Bus error
#

ls 一下，就会有如下的一些诡异现象：

# ls /bin/
Segmentation fault

# ls /
*** glibc detected *** -sh: malloc(): memory corruption: 0x33fb4af4 ***
Aborted

# ls /proc
Unhandled kernel unaligned access[#2]:
Cpu 0
$ 0 : 00000000 1000fc00 00000000 65532043
$ 4 : 65532043 00000000 00000000 00000000
$ 8 : 812c2006 00001000 812c2000 fffffff4
$12 : 0000002e 00004000 00600000 0000006c
$16 : 00000000 65532043 812c5cf4 812efd38
$20 : 00000000 877ac120 004a02f8 812efd40
$24 : 80000000 33f222d0
$28 : 812ee000 812efcb0 00000001 8003f568
Hi : 00000000
Lo : 00000004
epc : 8003f174 pid_task+0x1c/0x38 Not tainted
ra : 8003f568 get_pid_task+0x2c/0x88
Status: 1000fc03 KERNEL EXL IE
Cause : 00000010
BadVA : 65532053
PrId : 0002901a
Modules linked in:
Process sh (pid: 708, threadinfo=812ee000, task=8771f908)
Stack : 877ac120 812efd38 8009dd90 812efd38 812c2009 812a534c 800cab10 800900c0
812c2009 812efd40 812efe60 812efd38 812c2009 812c5cf4 812efe60 800901b8
811e3304 8009e564 812efe84 80330000 812c2009 812efd40 877a3dc4 812efe60
00000000 00000000 004a02f8 00000000 80092358 8009290c 80193fb4 8002e788
00008000 812efea5 877ac120 877a85ec 001313f5 00000003 812c2006 000012bf
...

Call Trace:
[<8003f174>] pid_task+0x1c/0x38
[<8003f568>] get_pid_task+0x2c/0x88
[<800cab10>] pid_revalidate+0x28/0x178
[<800901b8>] do_lookup+0x68/0x1fc
[<80092358>] __link_path_walk+0x5b0/0x1238
[<80093098>] link_path_walk+0xb8/0x1b4
[<800934fc>] do_path_lookup+0x140/0x36c
[<80094190>] __user_walk_fd+0x54/0x88
[<8008aa3c>] vfs_lstat_fd+0x28/0x68
[<8008aaa4>] sys_newlstat+0x28/0x50
[<8000d610>] syscall_trace_entry+0x70/0x90

Code: 03e00008 00001021 00021100 <8c630010> 00451023 00621023 1060fff9 2442ff34 03e00008
note: sh[708] exited with preempt_count 1
Segmentation fault

# ps ax
PID Uid VCPU 0 Unable to handle kernel paging request at virtual address 73656d20, epc == 800bf6f0, ra == 800bf6e8
mSize Stat CommaOops[#1]:
Cpu 0
$ 0 : 00000000 1000fc00 73656d20 7375621f
$ 4 : 81240568 73756220 00000000 87719854
$ 8 : 00000000 80370000 81253c50 ffffffff
$12 : 00000005 00000000 2aaa8290 7fcca278
$16 : 73656d18 877197fc 81240464 00000000
$20 : 81240560 00000020 00000020 81246e64
$24 : 00000000 801728e4
$28 : 81252000 81253e80 87719854 800bf6e8
Hi : 00000000
Lo : 00000d68
epc : 800bf6f0 inotify_inode_queue_event+0x94/0x160 Not tainted
ra : 800bf6e8 inotify_inode_queue_event+0x8c/0x160
Status: 1000fc03 KERNEL EXL IE
Cause : 80000008
BadVA : 73656d20
PrId : 0002901a
Modules linked in:
Process ps (pid: 636, threadinfo=81252000, task=87792c90)

Stack : 00000000 800833d4 00000000 00000000 00000000 00000000 81240568 00000000
875991d0 877197fc 81240464 00000000 87719854 00000020 00000000 00000000
00000000 800c0148 81225000 7fcca8b5 80082fc0 00000000 81246e64 0000416d
00000020 8123eb60 00000004 81246e64 81225000 7fcca8b5 80083488 11e1a2ff
386d4414 11e1a2ff 386d4414 11e1a2ff 00000400 00000000 000003ff 7fcca958
...

Call Trace:
[<800bf6f0>] inotify_inode_queue_event+0x94/0x160
[<800c0148>] inotify_dentry_parent_queue_event+0xd8/0x190
[<80083488>] do_sys_open+0xa0/0x174
[<8000d610>] syscall_trace_entry+0x70/0x90

Code: afa20018 8e0200fc 2450fff8 <16820007> 8e030008 0802fddf 8fa40018 26220008 02208021
nd
1 root 508 S init
2 root SWN [ksoftirqd/0]
3 root SW [watchdog/0]
4 root SW< [events/0]
5 root SW< [khelper]
6 root SW< [kthread]
20 root SW< [kblockd/0]
31 root SW [pdflush]
32 root SW [pdflush]
33 root SW< [kswapd0]
34 root SW< [aio/0]
35 root SW< [unionfs_siod/0]

Segmentation fault

执行其它的命令，亦会有类似的现象。

2 Analysis

通常的 "Segmentation fault" 系访问非法虚拟地址所致（页表没相应的映射）；"Bus error" 则常常是访问非对其的地址所致，例如从 0x8000 0003 读取一个字，大多数情况下内核会报 "Bus error"。

从几次内核 dump 出来的寄存器和栈来看，出现 "Segmentation fault" 的位置不固定，访问的非法地址差别较大，完全重现的概率微乎其微，因此从引起异常的指令，到函数，再到程序块的逆向分析思路根本行不通。印象中试了几次，几近抓狂。

后与 shyjuventus 聊起，此 BSP 在 2.6.14 的版本时没有任何问题，更新到 2.6.21 后每次到运行 busybox 时，就会 hung 掉（此时 cpu_has_dc_aliases = 1），强制将 cpu_has_dc_aliases = 0 则出现上面描述的 "Segmentation fault" 现象，而且更重要的：将 kernel 配置成 uncached (CONFIG_UNCACHED=y) 后，系统能正常运行，没有任何问题，并表示十分怀疑是 Cache Aliases 引起的问题。 shyjuventus 提供的信息，给从正面突破打开了一个口子。

查看内核启动日志后发现该 MIPS core 使用 32KB 2-way 的 DCache，且其用虚址索引、物址匹配，内核默认使用 4KB 的页大小，则 way_size = 32KB/2 = 16KB > 4KB，显然存在 Cache Aliases。加上用 uncached 的内核起没有问题，因此初步判断是由 Cache Aliases 引起的。

查看代码发现 cpu_has_dc_aliases 这个变量应该为 1，指示说明这个处理器有 Cache Aliases 问题，如将其强制定义成 0，则 Kernel 中为 Cache Aliases 准备的额外的 Cache flush 皆会被绕过，造成大量的父子进程间数据不一致。

由此将强制 0 赋值去除，则问题转化成：在 2.6.14 没有任何问题，2.6.21 则启动到运行 busybox 时就 hung 了。

3 Investigate

用 SysRq 的 t 键查看 hung 时，系统所有的 Task，惊奇的发现 pid == 1 的 init “蒸发”了。

很自然的，kgdb 上，艰苦卓绝的跟踪后发现是在 run_init_process("/sbin/init") 中挂了，

以行步进到 do_execve()，发现该函数能正确返回，继续跟踪发现在执行 syscall_exit 时挂的，眼见就能接近焦点，不幸的是，当单步到 restore_all 的第一条指令时， kgdb 的单步跟踪始终在不停的死循环，每次执行 si，PC 的值都不会变。尝试多次，无果。静心偶然想起，以前亦遇到过断点在异常返回代码中是 kgdb 常常不能正常工作，其原因大概是 kgdb 的实现亦依赖于内核的异常处理，应该是自己单步自己，搞出死循环了。

于是转而对比 2.6.21 相对于 2.6.14 所做的改进，期间和 yshi 闲聊，亦提到过 2.6.21 在一些地方使用 kmap_coherent 替换了 2.6.14 所用的 kmap_atomic，于是很快就找到了 5.4.3 节所提到的那个 patch。

稍作分析后，就尝试绕开所有使用 kmap_coherent 的代码（使用原 kmap_atomic + flush 的机制）发现没有 hung，可以进入 shell，但现象与将 cpu_has_dc_aliases 强制定义为 0 的现象类似，只是情况没那么糟糕，虽有 "Segmentation fault"、"Bus error" 但不太影响正常使用，显然是 kmap_coherent 导致了 hung。于是粗略判断为退回原有的机制，可能还有某些该 flush 的地方被疏漏了，如果将这些洞补上，应该就可以彻底消除这些讨厌的 "Segmentation fault" 了。

至此已有些眉目，考虑到市场的兄弟还等着发布，列了两个解决方向：

A. 保守的，也是最快的：参照 2.6.14，补上这些残余的疏漏；

B. 激进的，也是可能花时间很多的：使 kmap_coherent 工作正常。