25 BUG at check_bytes_and_report

异常现场：

当你在SYS_KERNEL_LOG里看到如下log，那么就属于BUG at check_bytes_and_report一类问题了：

<6>[ 492.558572]-(0)[1163:system_server]============================================================================= <6>[ 492.558599]-(0)[1163:system_server]BUG kmalloc-128 (Tainted: P W O ): Poison overwritten <6>[ 492.558621]-(0)[1163:system_server]----------------------------------------------------------------------------- <6>[ 492.558621] <6>[ 492.558649]-(0)[1163:system_server]INFO: 0xffffffc0553a93e9-0xffffffc0553a93e9. First byte 0x69 instead of 0x6b <6>[ 492.558685]-(0)[1163:system_server]INFO: Allocated in alloc_vmap_area.isra.31+0x6c/0x394 age=525 cpu=0 pid=8631 <6>[ 492.558708]-(0)[1163:system_server] alloc_debug_processing+0x184/0x194 <6>[ 492.558731]-(0)[1163:system_server] __slab_alloc.isra.55.constprop.64+0x5ac/0x5e8 <6>[ 492.558751]-(0)[1163:system_server] kmem_cache_alloc_trace+0x11c/0x240 <6>[ 492.558772]-(0)[1163:system_server] alloc_vmap_area.isra.31+0x68/0x394 <6>[ 492.558793]-(0)[1163:system_server] __get_vm_area_node.isra.32+0x98/0x190 <6>[ 492.558814]-(0)[1163:system_server] __vmalloc_node_range+0x64/0x284 <6>[ 492.558833]-(0)[1163:system_server] vmalloc+0x2c/0x38 <6>[ 492.558854]-(0)[1163:system_server] write_pmsg+0x58/0x148 <6>[ 492.558881]-(0)[1163:system_server]INFO: Freed in rcu_process_callbacks+0x230/0x988 age=179 cpu=0 pid=3 <6>[ 492.558902]-(0)[1163:system_server] free_debug_processing+0x1f4/0x328 <6>[ 492.558921]-(0)[1163:system_server] __slab_free+0x29c/0x374 <6>[ 492.558939]-(0)[1163:system_server] kfree+0x22c/0x270 <6>[ 492.558959]-(0)[1163:system_server] rcu_process_callbacks+0x22c/0x988 <6>[ 492.558979]-(0)[1163:system_server] __do_softirq+0xd8/0x36c <6>[ 492.558998]-(0)[1163:system_server] run_ksoftirqd+0x6c/0xec <6>[ 492.559020]-(0)[1163:system_server] smpboot_thread_fn+0x1fc/0x2c8 <6>[ 492.559039]-(0)[1163:system_server] kthread+0xd8/0xf0 <6>[ 492.559063]-(0)[1163:system_server]INFO: Slab 0xffffffbe020a4cf8 objects=12 used=12 fp=0x (null) flags=0x0080 <6>[ 492.559085]-(0)[1163:system_server]INFO: Object 0xffffffc0553a93c0 @offset=960 fp=0xffffffc0553a9640 <6>[ 492.559085] <6>[ 492.559116]-(0)[1163:system_server]Bytes b4 ffffffc0553a93b0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ <6>[ 492.559140]-(0)[1163:system_server]Object ffffffc0553a93c0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559165]-(0)[1163:system_server]Object ffffffc0553a93d0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559189]-(0)[1163:system_server]Object ffffffc0553a93e0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 69 6b 6b 6b 6b 6b 6b kkkkkkkkkikkkkkk <6>[ 492.559213]-(0)[1163:system_server]Object ffffffc0553a93f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559237]-(0)[1163:system_server]Object ffffffc0553a9400: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559261]-(0)[1163:system_server]Object ffffffc0553a9410: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559286]-(0)[1163:system_server]Object ffffffc0553a9420: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk <6>[ 492.559310]-(0)[1163:system_server]Object ffffffc0553a9430: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk. <6>[ 492.559333]-(0)[1163:system_server]Redzone ffffffc0553a9440: bb bb bb bb bb bb bb bb ........ <6>[ 492.559358]-(0)[1163:system_server]Padding ffffffc0553a94c0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ <6>[ 492.559382]-(0)[1163:system_server]Padding ffffffc0553a94d0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ <6>[ 492.559407]-(0)[1163:system_server]Padding ffffffc0553a94e0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ <6>[ 492.559431]-(0)[1163:system_server]Padding ffffffc0553a94f0: 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ <6>[ 492.559457]-(0)[1163:system_server]CPU: 0 PID: 1163 Comm: system_server Tainted: P B W O 3.18.22+ #1 <6>[ 492.559474]-(0)[1163:system_server]Hardware name: MT6755 (DT) <6>[ 492.559491]-(0)[1163:system_server]Call trace: <2>[ 492.559514]-(0)[1163:system_server][<ffffffc00008b970>] dump_backtrace+0x0/0x15c <2>[ 492.559534]-(0)[1163:system_server][<ffffffc00008badc>] show_stack+0x10/0x1c <2>[ 492.559557]-(0)[1163:system_server][<ffffffc000abb050>] dump_stack+0x74/0xb8 <2>[ 492.559578]-(0)[1163:system_server][<ffffffc0001c44fc>] print_trailer+0x140/0x288 <2>[ 492.559600]-(0)[1163:system_server][<ffffffc0001c471c>] check_bytes_and_report+0xd8/0x10c <2>[ 492.559622]-(0)[1163:system_server][<ffffffc0001c4968>] check_object+0x1ac/0x220 <2>[ 492.559644]-(0)[1163:system_server][<ffffffc0001c69a8>] alloc_debug_processing+0x110/0x194 <2>[ 492.559667]-(0)[1163:system_server][<ffffffc0001c7330>] __slab_alloc.isra.55.constprop.64+0x5ac/0x5e8 <2>[ 492.559689]-(0)[1163:system_server][<ffffffc0001c7958>] kmem_cache_alloc_trace+0x11c/0x240 <2>[ 492.559711]-(0)[1163:system_server][<ffffffc0000c1eac>] __async_schedule+0x34/0x1a8 <2>[ 492.559734]-(0)[1163:system_server][<ffffffc0000c2048>] async_schedule_domain+0x8/0x14 <2>[ 492.559759]-(0)[1163:system_server][<ffffffc0008da144>] dapm_power_widgets+0x618/0x8bc <2>[ 492.559783]-(0)[1163:system_server][<ffffffc0008dc17c>] snd_soc_dapm_stream_event+0xbc/0x110 <2>[ 492.559805]-(0)[1163:system_server][<ffffffc0008d04f8>] snd_soc_suspend+0x294/0x468 <2>[ 492.559829]-(0)[1163:system_server][<ffffffc000393e18>] platform_pm_suspend+0x20/0x50 <2>[ 492.559852]-(0)[1163:system_server][<ffffffc000399194>] dpm_run_callback+0x50/0x184 <2>[ 492.559873]-(0)[1163:system_server][<ffffffc00039ae98>] __device_suspend+0x128/0x3cc <2>[ 492.559894]-(0)[1163:system_server][<ffffffc00039b1e0>] dpm_suspend+0xa4/0x358 <2>[ 492.559915]-(0)[1163:system_server][<ffffffc00039b4fc>] dpm_suspend_start+0x68/0x78 <2>[ 492.559939]-(0)[1163:system_server][<ffffffc0000fe8d8>] suspend_devices_and_enter+0x98/0x2d0 <2>[ 492.559960]-(0)[1163:system_server][<ffffffc0000fefe4>] pm_suspend+0x3c4/0x5c8 <2>[ 492.559982]-(0)[1163:system_server][<ffffffc0000fd5b0>] state_store+0xb0/0xe0 <2>[ 492.560004]-(0)[1163:system_server][<ffffffc0003270c4>] kobj_attr_store+0x10/0x24 <2>[ 492.560026]-(0)[1163:system_server][<ffffffc00023996c>] sysfs_kf_write+0x3c/0x48 <2>[ 492.560049]-(0)[1163:system_server][<ffffffc000238ef4>] kernfs_fop_write+0x10c/0x178 <2>[ 492.560070]-(0)[1163:system_server][<ffffffc0001d0808>] vfs_write+0x98/0x1b8 <2>[ 492.560091]-(0)[1163:system_server][<ffffffc0001d0f40>] SyS_write+0x40/0xa0 <2>[ 492.560124]-(0)[1163:system_server]BUG: failure at kernel-3.18/mm/slub.c:796/check_bytes_and_report()! <6>[ 492.561176]-(0)[1163:system_server][klog]fault_level=0x7(data abort(aarch64)), fault_type=6, fault_msg=level 2 translation fault <6>[ 492.561201]-(0)[1163:system_server]Unable to handle kernel paging request at virtual address 0000dead <6>[ 492.561220]-(0)[1163:system_server]pgd = ffffffc03c136000 <2>[ 492.561229]-(0)[1163:system_server][0000dead] *pgd=00000000802de003, *pud=00000000802de003, *pmd=0000000000000000 <6>[ 492.561283]-(0)[1163:system_server][klog]fault already exists:0x7, ignore:0x2 <6>[ 492.561306]-(0)[1163:system_server]Internal error: Oops: 96000046 [#1] PREEMPT SMP <2>[ 492.561316]-(0)[1163:system_server]disable aee kernel api <6>[ 492.561350]-(0)[1163:system_server]CPU: 0 PID: 1163 Comm: system_server Tainted: P B W O 3.18.22+ #1 <6>[ 492.561369]-(0)[1163:system_server]Hardware name: MT6755 (DT) <6>[ 492.561395]-(0)[1163:system_server]task: ffffffc03b158000 ti: ffffffc02f018000 task.ti: ffffffc02f018000 <6>[ 492.561418]-(0)[1163:system_server]PC is at check_bytes_and_report+0x108/0x10c <6>[ 492.561441]-(0)[1163:system_server]LR is at check_bytes_and_report+0x100/0x10c

代码位置：

kernel-3.18/mm/slub.c

static int check_bytes_and_report(struct kmem_cache *s, struct page *page, u8 *object, char *what, u8 *start, unsigned int value, unsigned int bytes)
{
    u8 *fault;
    u8 *end;

    fault = memchr_inv(start, value, bytes);
    if (!fault)
        return 1;

    end = start + bytes;
    while (end > fault && end[-1] == value)
    end--;

    slab_bug(s, "%s overwritten", what);
    pr_err("INFO: 0x%p-0x%p. First byte 0x%x instead of 0x%x\n", fault, end - 1, fault[0], value);
    print_trailer(s, page, object);

    BUG(); /* 这里发生KE */
    restore_bytes(s, what, value, fault, end);
    return 0;
}

问题解读：

slub是kernel非常重要的内存分配器（详情请看：doc/Documentation/vm/slub.txt），是基于buddy system分配器之上再细化的。其接口就是kmalloc()/kfree()等一系列函数，在kernel里被广泛使用。

任何内存管理相关的问题，slub也会有。比如：

• use after free。通过kmalloc()申请内存，用完之后kfree()释放，但是后面又再使用了这块释放的内存。
• 内存踩坏。
  • 通过kmalloc()申请的内存，使用时超出了当时申请的尺寸，将不属于你的内存踩坏了。
  • 其他模块意外将slub空闲/使用中的内存踩坏。
• double free。对一块kmalloc()申请的内存连续调用2次kfree()函数。
• HW故障。比如DRAM/CPU不稳定，导致原有的内存发生跳变，bitflip。上面的例子就是发生了bitflip，6b跳变为69了。

如何检查slub里是否发生异常呢？这就需要额外的内存做守卫了，kernel已有这样的功能，只要打开CONFIG_SLUB_DEBUG，kfree()后的内存会被格式化成6b，还有red zone格式化成bb，padding为5a，还有每次申请和释放都会记录调用栈，记录谁申请/释放的。在每次的内存申请都会做相关检查，如果出现故障，就会抛出对应的log并主动调用BUG()

问题解决：

• use after free。需要通过slub记录的调用栈找凶手，检查代码逻辑才行。
• 内存踩坏。通过slub记录的调用栈或采用MMU保护，请参考：[FAQ14614]如何用MMU保护buddy system？
• double free。从slub记录的调用栈可以很明显看出。
• bitflip。直接要硬件交叉比对（CPU/DRAM），排查硬件故障，上面的log的例子直接HW交叉比对。