一般情况下，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进程后卡死了，但具体是里面操作哪个模块卡死的，还需要进一步打桩进行定位。
