一般情况下,Linux系统在死机时会产生一些dump信息,例如oops,通过分析oops信息就可以基本定位问题所在,但有些特殊情况下死机时,没有任何的打印的信息。如果直接使用printk等打印排查问题,有可能会因为printk输出缓慢改变了系统运行的时序,导致问题无法复现,而且在中断里使用printk将大大降低系统性能。如果有DS-5等硬件调试工具,那是最好的,如果没有,那么这时候可以借助一种特殊手段来排查问题,也就是内存日志。
本文所描述的内存日志,并不是将内核的printk重定向到内存中,因为printk的打印太多了,如果将日志写入到内存中,那就比正常的串口printk快的多,对系统的影响最小。简而言之,这种方法就是将关键模块的日志保存在内存中,等到下一次启动时,再将这些日志全部dump出来。这里有两个需要注意的地方:
1、为了尽可能地减小日志大小,写入的日志为16进制格式,自己定义好协议即可,最后看日志的时候,再将16进制日志翻译成自己能看懂的格式。
2、这种方法对DDR有一定的要求,要求死机后复位重启(非断电重启)后DDR里的数据能保持。笔者的板子由于有PMIC给SOC供电,DDR是额外供电的,复位时只复位PMIC,因此DDR数据能保持。另外笔者试过,有些平台看门狗复位后DDR的数据能继续保持,有些则不行,可以做个小实验:在kernel中使用devmem命令在高地址中写入一个特殊数据,然后利用看门狗溢出进行复位,复位后在uboot里将这个地址的数据打印出来,看是否一致,如果一致就说明看门狗复位后DDR数据不会丢失,可以使用这种方法。
下面是我实现的一个mem_log模块,可以根据自己的需求适当修改,例如在每条日志里增加系统的jffies等。笔者板子内存为128M,物理地址空间为0x80000000 ~ 0x87FFFFFF,将最高1M地址空间给mem_log使用,但笔者实际只使用了其中的28KB,因为mem_log的核心是记录cpu的遗言,不需要太大的空间,这可以自行调整。下面是mem_record_t的核心成员的定义:
- index:日志的序号,每记录一条会自增1,最后排查时就是根据index的连续性找到最后一条日志。
- module:用户自定义的模块,例如中断、线程调度、各种外设驱动等。
- flag:标志位,可以用来记录函数进入和退出,是在哪个cpu核上运行等。
- args:参数,当记录的模块为中断时,args可以保存中断号;同理,当记录的模块为线程时,可以保存切入和切出的线程名;当记录的模块为外设驱动时,可以保存驱动名称。
#include "linux/mem_log.h"
#include <linux/spinlock.h>
#include <linux/kernel.h>
#include <asm/io.h>
#define MEM_LOG_START_ADDR (0x87F00000) /* mem_log的起始物理地址 */
#define MEM_LOG_SIZE (28*1024L) /* mem_log的大小 */
typedef struct
{
unsigned int index;
unsigned char module;
unsigned char flag;
unsigned char args[10];
}mem_record_t;
static volatile unsigned int *log_mem_addr = NULL;
static unsigned int mem_log_index = 0;
static mem_record_t *wrecord = NULL;
#ifdef CONFIG_SMP
static DEFINE_SPINLOCK(mem_log_spinlock);
#endif
void mem_log_init(void)
{
log_mem_addr = ioremap(MEM_LOG_START_ADDR, MEM_LOG_SIZE);
if(!log_mem_addr)
{
printk(KERN_EMERG"mem_log_init failed.");
return;
}
wrecord = (mem_record_t*)log_mem_addr;
}
EXPORT_SYMBOL(mem_log_init);
void mem_log_clear(void)
{
if(log_mem_addr)
{
memset((void*)log_mem_addr , 0xFF, MEM_LOG_SIZE);
}
}
EXPORT_SYMBOL(mem_log_clear);
void mem_log_record(uint8_t module, uint8_t flag, uint8_t *args, uint8_t args_len)
{
#ifdef CONFIG_SMP
unsigned long flags;
#endif
static int print = 0;
if(!wrecord)
{
if(!print)
{
print = 1;
printk(KERN_EMERG"please use mem_log_init first.\n");
}
return;
}
#ifdef CONFIG_SMP
spin_lock_irqsave(&mem_log_spinlock, flags);
#endif
wrecord->index = mem_log_index++;
wrecord->module = module;
#ifdef CONFIG_SMP
wrecord->flag = (flag << 4) | smp_processor_id();
#else
wrecord->flag = (flag << 4);
#endif
memcpy(wrecord->args, args, args_len);
wrecord = wrecord + 1;
/* 日志写满后从头覆盖写 */
if((unsigned int)wrecord >= ((unsigned int)log_mem_addr + MEM_LOG_SIZE))
{
wrecord = (mem_record_t*)log_mem_addr;
}
#ifdef CONFIG_SMP
spin_unlock_irqrestore(&mem_log_spinlock, flags);
#endif
}
EXPORT_SYMBOL(mem_log_record);
void mem_log_dump(void)
{
mem_record_t *record = (mem_record_t*)log_mem_addr;
uint32_t index_back = record->index;
uint8_t found = 0;
printk("mem log dump:\n");
printk("record:%X, end:%X\n", (unsigned int)record, ((unsigned int)log_mem_addr + MEM_LOG_SIZE));
for(; (unsigned int)record < ((unsigned int)log_mem_addr + MEM_LOG_SIZE) ; )
{
printk("%08X %02X %02X %02X%02X%02X%02X%02X%02X%02X%02X%02X%02X\n",
record->index, record->module, record->flag,
record->args[0],record->args[1],record->args[2],record->args[3],record->args[4],
record->args[5],record->args[6],record->args[7],record->args[8],record->args[9]);
record++;
if(!found)
{
if((index_back+1) != record->index)
{
found = 1;
continue;
}
index_back = record->index;
}
}
/* 找到最后一条index不连续的日志, 即死机前的最后一条日志 */
printk("find last log index:%08X!\n", index_back);
}
EXPORT_SYMBOL(mem_log_dump);
以下是对应的头文件,我定义了三个模块:中断、线程退出、线程切入,当然还可以定义其他一些模块,例如我怀疑SD驱动有问题,可以定义SD模块。Flag只定义了函数进入和函数退出,如果最后的日志只有MEM_LOG_FLAG_FUNC_IN而没有MEM_LOG_FLAG_FUNC_OUT,那么恭喜,就是卡死在这个函数里了。
#ifndef _LINUX_MEM_LOG_H
#define _LINUX_MEM_LOG_H
#include "linux/string.h"
#define MEM_LOG_MODULE_IRQ (0x11)
#define MEM_LOG_MODULE_THREAD_PRE (0x22)
#define MEM_LOG_MODULE_THREAD_NEXT (0x33)
#define MEM_LOG_FLAG_FUNC_IN (0x01)
#define MEM_LOG_FLAG_FUNC_OUT (0x02)
void mem_log_init(void);
void mem_log_clear(void);
void mem_log_record(uint8_t module, uint8_t flag, uint8_t *args, uint8_t args_len);
void mem_log_dump(void);
#endif
由于我的板子是直接从TF卡引导kernel启动,没有uboot阶段,因此重启的日志直接从kernel里打印,我将打印加在了内核启动时的start_kernel函数里:
asmlinkage __visible void __init __no_sanitize_address start_kernel(void)
{
char *command_line;
char *after_dashes;
set_task_stack_end_magic(&init_task);
smp_setup_processor_id();
debug_objects_early_init();
……
console_init();
if (panic_later)
panic("Too many boot %s vars at `%s'", panic_later,
panic_param);
lockdep_init();
mem_log_init();
mem_log_dump();
mem_log_clear();
/*
* Need to run this when irqs are enabled, because it wants
* to self-test [hard/soft]-irqs on/off lock inversion bugs
* too:
*/
locking_selftest();
……
}
首次上电时,由于先前没有记录任何日志,所以mem_log_dump会打印一堆脏数据,无需关心。此时mem_log已经初始化完成,在DDR高地址区域开辟了一块空间专门给mem_log使用,需要注意内核不能再使用这段内存,因此需要修改bootargs中的mem参数。此时已经可以在可疑的地方进行打桩,我们知道,程序的执行无外乎两个地方:线程和中断,因此我在这两个地方用mem_log_record函数进行打桩,下面是伪代码示意。
/* 在线程调度的地方打桩 */
static void __sched notrace __schedule(bool preempt)
{
……
mem_log_record(MEM_LOG_MODULE_THREAD_PRE, MEM_LOG_FLAG_FUNC_IN, (uint8_t*)prev->comm, 10);
mem_log_record(MEM_LOG_MODULE_THREAD_NEXT, MEM_LOG_FLAG_FUNC_IN, (uint8_t*)next->comm, 10);
rq = context_switch(rq, prev, next, &rf);
mem_log_record(MEM_LOG_MODULE_THREAD_PRE, MEM_LOG_FLAG_FUNC_OUT, (uint8_t*)prev->comm, 10);
mem_log_record(MEM_LOG_MODULE_THREAD_NEXT, MEM_LOG_FLAG_FUNC_OUT,(uint8_t*)next->comm, 10);
……
}
/* 在中断入口打桩 */
int __handle_domain_irq(struct irq_domain *domain, unsigned int hwirq,
bool lookup, struct pt_regs *regs)
{
……
irq_enter();
mem_log_record(MEM_LOG_MODULE_IRQ, MEM_LOG_FLAG_FUNC_IN, (uint8_t*)&hwirq, 4);
……
generic_handle_irq(irq);
……
mem_log_record(MEM_LOG_MODULE_IRQ, MEM_LOG_FLAG_FUNC_OUT, (uint8_t*)&hwirq, 4);
irq_exit();
……
}
下面是我的板子死机的实际样例,下面是死机复位后dump的日志,mem_log会找到最后一个不连续的index日志:
可以看到最后截断的日志序号是6F7278BD,将上述日志翻译一下,如下:
可以看到,最后是切换到arecord进程后卡死了,但具体是里面操作哪个模块卡死的,还需要进一步打桩进行定位。