Linux死机排查方法—

Linux死机排查方法——内存日志

一般情况下，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);
#endifvoid 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_SMPunsigned long flags;
#endifstatic int print = 0;if(!wrecord){if(!print){print = 1;printk(KERN_EMERG"please use mem_log_init first.\n");			}return;}
#ifdef CONFIG_SMPspin_lock_irqsave(&mem_log_spinlock, flags);
#endif	wrecord->index = mem_log_index++;wrecord->module = module;
#ifdef CONFIG_SMPwrecord->flag = (flag << 4) | smp_processor_id();
#elsewrecord->flag = (flag << 4);
#endifmemcpy(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_SMPspin_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日志：