Mcelog笔记

    最近测试过程中panic并报如下错误：

Kernel panic - not syncing: Timeout synchronizing machine check over CPUs

经查找Linux内核代码是与mce相关的错误导致的系统panic。

    收集mce的log信息，需要安装mcelog工具。Mcelog能够记录和统计运行在x86架构下的Linux OS的一些machine check信息，包括内存、IO和CPU硬件的特定错误。

安装mcelog

    安装mcelog的办法：

    1、 在debian系统上apt-get install mcelog。安装完成之后，service mcelog status查看状态检查是否mcelog服务是否已启动。

    2、 从http://www.mcelog.org上下载源码下来，按照安装手册进行编译安装。

    安装完成之后会在/var/log/下面看到mcelog文件。文件内容的格式如下：

Hardware event. This is not a software error. MCE 0 CPU 0 BANK 7 MISC 2050008086 ADDR 464bdd6c0 TIME 1453186107 Tue Jan 19 14:48:27 2016 MCG status: MCi status: Error overflow Corrected error MCi_MISC register valid MCi_ADDR register valid MCA: MEMORY CONTROLLER RD_CHANNEL2_ERR Transaction: Memory read error STATUS cc0002c000010092 MCGSTATUS 0 MCGCAP 1000c15 APICID 0 SOCKETID 0 CPUID Vendor Intel Family 6 Model 62

图1 MCE日志

上面每条的信息代表的含义这里先不展开。

Mcelog运行模式

    Mcelog有以下几种运行模式：

    1、 cronjob

    2、 trigger

    3、 dameon

Cronjob

    定时任务是一种比较老的方式。Mcelog每5分钟运行一次收集错误，这种方式的缺点就是延迟了错误的上报。 

    在mcelog源码包中有一个mcelog.cron脚本，里面的内容如下：

#!/bin/bash /usr/sbin/mcelog --ignorenodev --filter >> /var/log/mcelog

       上面脚本就是在每次定时任务到期执行时运行/usr/sbin/mcelog，并将记录的日志信息写到/var/log/mcelog文件中。

Trigger

    触发模式是在错误发生时内核运行mcelog。文档中提到的配置方式为：

echo /usr/sbin/mcelog > /sys/devices/system/machinecheck/machinecheck0/trigger

       /sys下的接口trigger对应的内核代码如下：

static ssize_t  show_trigger(struct device *s, struct device_attribute *attr, char *buf)   {           strcpy(buf, mce_helper);           strcat(buf, "\n");           return strlen(mce_helper) + 1;   }      static ssize_t set_trigger(struct device *s, struct device_attribute *attr,  const char *buf, size_t siz)   {           char *p;              strncpy(mce_helper, buf, sizeof(mce_helper));           mce_helper[sizeof(mce_helper)-1] = 0;           p = strchr(mce_helper, '\n');              if (p)                   *p = 0;               return strlen(mce_helper) + !!p;   }

    由上面的代码可知配置trigger模式就是将/usr/sbin/mcelog写入mce_helper的过程。那么mce_helper是用来做什么的呢？

    原来在mce_notify_irq中会判断mce_helper的值。mce_notify_irq函数在中断上下文中被调用，用来通知用户态程序machine check event发生了。

/*     * Notify the user(s) about new machine check events.     * Can be called from interrupt context, but not from machine check/NMI     * context.     */   int mce_notify_irq(void)   {             if (test_and_clear_bit(0, &mce_need_notify)) {                   /* wake processes polling /dev/mcelog */                    wake_up_interruptible(&mce_chrdev_wait);                      if (mce_helper[0])   /*检查是否有配置*/                         schedule_work(&mce_trigger_work);  /*向工作队列提交新的工作*/      …… }

    接下来看看工作队列mce_trigger_work做了些什么事情？

static void mce_do_trigger(struct work_struct *work)   {           call_usermodehelper(mce_helper, mce_helper_argv, NULL, UMH_NO_WAIT);   }     static DECLARE_WORK(mce_trigger_work, mce_do_trigger);

    工作队列mce_trigger_work就是通过call_usermodehelper函数在内核态运行用户态的程序，这里就是运行我们配置的/usr/sbin/mcelog程序。

    上面是trigger触发模式运行过程一个简单分析。每次有machine check event事件发生时都会调用一次/usr/sbin/mcelog程序，文档中说这种方式虽然比较快的上报mce错误，但是负载很高。

Daemon模式

    启动mcelog服务之后，用ps查找mce相关的进程你会看到如下信息：

    看来我们的mcelog默认起来就是daemon守护进程的模式。这种模式下mcelog持续的作为后台的守护进程运行，并等待着错误的发生。

    上面看到的后台守护进程是怎么启动的？如下所示，看到此服务是运行脚本/etc/init.d/mcelog启动的。

    下面分析下mcelog用户态程序的代码看看在daemon模式下是如何运行的？

    从mcelog.c的main函数开始分析：

Step1:调用parse_config函数解析指定—daemon参数情况下设置daemon_mode=1

Step2：打开/dev/mcelog设备，并通过ioctl命令获取对应信息。

fd = open(logfn, O_RDONLY);  /*打开/dev/mcelog设备*/   if (ioctl(fd, MCE_GET_RECORD_LEN, &d.recordlen) < 0)           err("MCE_GET_RECORD_LEN");   if (ioctl(fd, MCE_GET_LOG_LEN, &d.loglen) < 0)           err("MCE_GET_LOG_LEN");

    首先是打开/dev/mcelog设备，获取fd，然后通过ioctl下发MCE_GET_RECORD_LEN命令和MCE_GET_LOG_LEN命令。

   查看arch/x86/kernel/cpu/mcheck/mce.c文件中的混杂设备mce_chrdev_device的fops操作集的unlocked_ioctl函数mce_chrdev_ioctl。

    MCE_GET_RECORD_LEN命令获取到的是每条记录的长度，对应的是内核中struct mce结构体的大小，其成员内容如下，用户态mcelog程序中的struct mce与此完全一样：

struct mce {        __u64 status;        __u64 misc;        __u64 addr;        __u64 mcgstatus;        __u64 ip;        __u64 tsc;  /* cpu time stamp counter */        __u64 time; /* wall time_t when error was detected */        __u8  cpuvendor; /* cpu vendor as encoded in system.h */        __u8  inject_flags; /* software inject flags */        __u16  pad;        __u32 cpuid; /* CPUID 1 EAX */        __u8  cs;  /* code segment */        __u8  bank; /* machine check bank */        __u8  cpu;  /* cpu number; obsolete; use extcpu now */        __u8  finished;   /* entry is valid */        __u32 extcpu; /* linux cpu number that detected the error */        __u32 socketid; /* CPU socket ID */        __u32 apicid; /* CPU initial apic ID */        __u64 mcgcap; /* MCGCAP MSR: machine check capabilities of CPU */   } ;

    MCE_LOG_LEN命令获取的是记录的mce信息的最大次数。获取到上面两个值之后，将两值乘起来，然后申请这么大的内存。

Step3:下面就是daemon模式下实现的主体

if (daemon_mode) {       …          register_pollcb(fd, POLLIN, process_mcefd, &d);  /*注册回调函数process_mcefd*/     …            event_signal(SIGUSR1);            eventloop();    /*poll循环执行已注册的回调函数*/

    上面代码中首先是调用register_pollcb函数注册回调函数process_mcefd，在eventloop函数中会遍历执行已注册的回调函数。

    process_mcefd函数的主题就是在POLLIN事件发生时，执行process函数。

static void process(int fd, unsigned recordlen, unsigned loglen, char *buf)    {                len = read(fd, buf, recordlen * loglen);              count = len / (int)recordlen;  /*计算记录的条数*/         if (count == (int)loglen) {                   if ((ioctl(fd, MCE_GETCLEAR_FLAGS, &flags) == 0) &&  (flags & (1 << MCE_OVERFLOW)))                           Eprintf("Warning: MCE buffer is overflowed.\n");           }              for (i = 0; (i < count) && !finish; i++) {                   struct mce *mce = (struct mce *)(buf + i*recordlen);                   mce_prepare(mce);   /*获取当前时间信息*/                  if (!dump_raw_ascii) {                           disclaimer();                           Wprintf("MCE %d\n", i);                           dump_mce(mce, recordlen);                   } else                           dump_mce_raw_ascii(mce, recordlen);                   flushlog();           }

    1、首先看下几个参数：fd为打开/dev/mcelog的文件描述符，recordlen为每条记录的长度，loglen是记录的最大个数，buf就是前面step2中看到的根据记录长度*最大记录个数乘积申请的内存。

    2、调用read函数从/dev/mcelog中读取machine check信息，存入buf中，读取到的信息长度为len。

    3、根据总长度len除以每条记录的长度计算出记录的个数。如果记录的个数等于最大个数，则通过ioctl命令通知内核将mcelog的flag值清零。如果设置成功，则打印“MCE buffer is overflowed”的告警信息。

    4、接下来的for循环就是逐条的读取MCE记录信息。

    ◆disclaimer意思是免责申明，此函数打印的就是“Hardware event. This is not a software error.”，明确的说明这不是软件的错误，这是最开心的事情。

    ◆dump_mce函数就是打印上图1-MCE日志中看到的信息。竟然不是软件问题，这里也不做分析了。

上面代码是daemon模式如何从/dev/mcelog中读取MCE信息并存储到/var/log/mcelog的一个过程分析。

Mcelog相关文件

    ◆/var/log/mcelog文件是在mcelog.c文件的main函数中调用modifier_finish函数创建的。

    ◆/dev/mce字符设备，用户态程序通过读取此设备，来获取可读的MCE信息。

内核收集MCE

    MCE的运行需要内核打开相关的配置选项，具体可查找config文件，默认是打开的。

    MCE日志的收集大体上可以分为三部分：

◆正常运行时MCE信息的收集

◆系统启动时对之前MCE信息的收集

◆系统panic时MCE信息的收集

    内核在启动的过程中就会初始化MCE相关的一些事宜，跟着系统启动的代码看看是怎么实现的。

初始化部分

Start_kernel-->check_bugs-->identify_boot_cpu-->identify_cpu-->mcheck_cpu_init：

void mcheck_cpu_init(struct cpuinfo_x86 *c)   {  …         if (!mce_available(c))                   return;             if (__mcheck_cpu_cap_init() < 0 || __mcheck_cpu_apply_quirks(c) < 0)                 mca_cfg.disabled = true;                   return;           }             machine_check_vector = do_machine_check;             __mcheck_cpu_init_generic();           __mcheck_cpu_init_vendor(c);           __mcheck_cpu_init_timer();           INIT_WORK(&__get_cpu_var(mce_work), mce_process_work);           init_irq_work(&__get_cpu_var(mce_irq_work), &mce_irq_work_cb);   }

    1、 mce_available函数是通过CPUID指令返回的EDX寄存器中的值判断处理器是否支持MCE特性。如果不支持则return返回。

    2、 __mcheck_cpu_cap_init函数主要是MCE初始化工作。读取MSR_IA32_MCG_CAP寄存器，bit0~7表示此处理器中硬件单元错误报告槽数（hardware unit error-reporting banks）。每一个bank包含有槽控制寄存器（IA32_MCi_CTL）、槽状态寄存器（IA32_MCi_STATUS）、槽地址寄存器（IA32_MCi_ADDR）和槽多功能寄存器（IA32_MCi_MISC）。

    我使用的Intel(R) Xeon(R) CPU E5-2690 v2 @ 3.00GHz机器上bank个数为27，使用的内核3.17.7中当从寄存器读取的banks大于32时，banks个数为32。我们可以通过如下命令查看当前环境下MCE的banks个数：

cat /sys/devices/system/machinecheck/machinecheck0/bank* |wc –l

    3、 初始化MCE处理函数为do_machine_check

    4、 __mcheck_cpu_init_generic函数主要的工作就是遍历每个bank，查看系统热复位之前写到每个bank中的MCE event，并将其记录到mcelog。在读取了bank中log之后会将此bank对应的状态寄存器值clear，这样在后面timer中就不会重复的读取了。

    首先读取相关的寄存器，初始化前面提到过的struct mce结构体的成员变量。这个过程对照Intel手册看看就行，下面重点看下是如何在mce_log函数中将信息记录到mcelog的。

for (;;) {           entry = rcu_dereference_check_mce(mcelog.next);  /*找到写的组内偏移*/         for (;;) {                     if (entry >= MCE_LOG_LEN) {      /*溢出*/                         set_bit(MCE_OVERFLOW, (unsigned long *)&mcelog.flags);                           return;                   }                   if (mcelog.entry[entry].finished) {  /*已填充MCE log*/                         entry++;                           continue;                   }                   break;           }           next = entry + 1;           if (cmpxchg(&mcelog.next, entry, next) == entry)  /*原子更新next成员*/                 break;   }    memcpy(mcelog.entry + entry, mce, sizeof(struct mce));  /*信息保存到mcelog */ mcelog.entry[entry].finished = 1;

    mcelog全局变量类型为struct mce_log，其中entry成员变量是一个大小为MCE_LOG_LEN的数组，数组每个成员大小为recordlen。next表示下一个写的数组内偏移。上面两层for循环干的事情就是找到一个合适的数组内位置，并将MCE event写到mcelog中。

    5、__mcheck_cpu_init_timer函数会启动一个timer，来定时读取MCE event，并写到mcelog中。这里就是系统运行运行时，MCE信息的收集机制。

    上面的代码我们看到了在系统启动的过程中是如何从寄存器读取热复位之前记录的MCE events信息写到mcelog中的，以及在系统运行过程中通过定时器读取MCE event的。

   在内核启动的后面驱动初始化部分还有与MCE相关的部分，代码在device_initcall_sync(mcheck_init_device)中。

    mcheck_init_device的主要代码如下：

mce_init_banks();   err = subsys_system_register(&mce_subsys, NULL); cpu_notifier_register_begin();   for_each_online_cpu(i) {           err = mce_device_create(i);           if (err) {                      __register_hotcpu_notifier(&mce_cpu_notifier);                    cpu_notifier_register_done();                    goto  err_device_create;           }   }   __register_hotcpu_notifier(&mce_cpu_notifier);   cpu_notifier_register_done();   register_syscore_ops(&mce_syscore_ops);     err = misc_register(&mce_chrdev_device);

    1、 mce_init_banks函数用来初始化/sys接口下的各个bank

    /sys/devices/system/machinecheck/machinecheck0/bank*

    2、 调用subsys_system_register来注册/sys/device/system下面的machinecheck

    3、 接下来遍历online cpu，创建相应的接口

    4、 注册字符设备/dev/mcelog。

    下面看下字符设备/dev/mcelog的操作集mce_chrdev_ops相关的代码。

static const struct file_operations mce_chrdev_ops = {         .open   = mce_chrdev_open,         .release  = mce_chrdev_release,         .read   = mce_chrdev_read,         .write   = mce_chrdev_write,         .poll   = mce_chrdev_poll,         .unlocked_ioctl    = mce_chrdev_ioctl,         .llseek   = no_llseek,    };

    在用户态mcelog程序打开/dev/mcelog后，在process函数中read读取设备信息最终调用的就是mce_chrdev_read函数。

    mce_chrdev_read函数首先调用__mce_read_apei函数来从ERST中读取上次系统panic时写到ERST中的MCE信息。ERST（Error Record Serialization Table）是一种永久存储错误的抽象接口。软件可以通过ERST将各种错误信息保存到ERST，再由ERST写入到可永久存储的物理介质中。在从ERST中读取了MCE信息后，还会接着从mcelog中读取，最终将所有读取到的MCE信息写到/var/log/mcelog文件中。

异常处理

    在前面初始化部分看到，MCE的异常处理函数为do_machine_check。在trap_init函数中当CONFIG_X86_MCE内核选项打开的情况下初始化int 18对应的中断描述符表。

#ifdef CONFIG_X86_MCE             set_intr_gate_ist(X86_TRAP_MC, &machine_check, MCE_STACK);   #endif

    当处理器检测到一个硬件错误或者总线错误，或者外部设备检测到一个总线错误，就会产生int 18。

    下面分析do_machine_check函数：

mce_gather_info(&m, regs);   final = &__get_cpu_var(mces_seen);   *final = m;     memset(valid_banks, 0, sizeof(valid_banks));   no_way_out = mce_no_way_out(&m, &msg, valid_banks, regs);      if (!(m.mcgstatus & MCG_STATUS_RIPV))  /*判断MCA状态寄存器RIPV 位是否设置*/         kill_it = 1;

do_machine_check代码片段-1

    mce_gather_info函数用来读取MCE发送时刻的现场信息，包括所在的CPU、时间、全局MCA状态寄存器(MSR_IA32_MCG_STATUS)值、ip寄存器值等。

    mce_no_way_out函数会遍历所有的槽(Banks)，读取槽状态寄存器(MCx_STATUS)，当bit63位为1，表示此槽状态寄存器有效，设置位图valid_banks中此槽对应的位。当panic_on_oops有设置或者容忍度tolerant小于1的情况下，返回1，也就是no_way_out=1。

    全局MCA状态寄存器的0位（RIPV），此位表示是否重新启动IP有效。如果RIPV位没有设置，则设置kill_it=1。

order = mce_start(&no_way_out);    /*所有cpu排序等待*/ for (i = 0; i < cfg->banks; i++) {           …         m.status = mce_rdmsrl(MSR_IA32_MCx_STATUS(i));  /*判断槽状态寄存器的bit63是否置位*/         if ((m.status & MCI_STATUS_VAL) == 0)                   continue;           /*当不是无法更正错误时，并且no_way_out为0时，不做处理*/         if (!(m.status & (cfg->ser ? MCI_STATUS_S : MCI_STATUS_UC)) &&  !no_way_out)                   continue;              add_taint(TAINT_MACHINE_CHECK, LOCKDEP_NOW_UNRELIABLE);           severity = mce_severity(&m, cfg->tolerant, NULL);           if (severity == MCE_KEEP_SEVERITY && !no_way_out)                   continue;           __set_bit(i, toclear);          if (severity == MCE_NO_SEVERITY) {                     continue;          }          mce_read_aux(&m, i);             if (severity == MCE_AO_SEVERITY && mce_usable_address(&m))                    mce_ring_add(m.addr >> PAGE_SHIFT);          mce_log(&m);          if (severity > worst) {                   *final = m;                   worst = severity;          }   } m = *final;        if (mce_end(order) < 0)      no_way_out = worst >= MCE_PANIC_SEVERITY;

do_machine_check代码片段-2

    上面的代码片段会遍历所有的banks，这个遍历过程是cpu按照进入此异常处理函数的顺序进行的，两个cpu共享的bank错误不会重复的上报。

    mce_start函数首先对全局变量mce_callin做原子加1操作，并返回结果给order。如果mce_callin值不等于online cpu个数，也就是还有cpu未进入此异常处理函数，则在timeout（1s）时间内等待；如果等待超时，则在容忍级别小于1的情况下panic。如果所有的cpu都已进入此异常处理函数，则mce_callin值等于online cpu个数，就不在此等待。接下来就会按照cpu进入此异常处理函数的顺序来遍历所有的banks，例如第一个进入的Cpu的order=1，则会首先执行；第二个进入的cpu的order=2，这样mce_executing=1小于order，就会等待timeout的时间，同理之后进入的cpu也会等待，只有在第一个cpu执行了mce_end，将mce_executing加1，第二个进入的cpu才会跳过这里的等待，往下执行。依次类推，所有的online cpu都会按照这个进入异常处理函数的顺序执行遍历banks的动作。

    在for循环中遍历bakns：首先读取槽(bank)状态寄存器(MCx_STATUS)，如果VAL位(bit63)为0，表示此槽的状态寄存器无效，直接continue遍历下一个bank。如果不是无法更正的错误，并且no_way_out=0的情况下，此MCE交由machine_check_poll函数在timer中来处理，这里就直接continue遍历下一个bank。

    mce_end函数首先对mce_executing变量原子加1。进入此异常处理函数的cpu，等待所有其他online cpu执行完上面的for循环，进入mce_end函数将mce_executing不断加加，直到等于cpu个数。第一个进入的cpu则还要在等到所有的cpu mce_executing变量原子加1之后，将mce_callin和mce_executing原子变量清零。其他等待的cpu再mce_executing被清零之后，直接返回退出。这里将两个原子变量清零，是为了下一次的MCE产生时do_machine_check异常处理函数的正常运行。

    上面分析了异常处理函数遍历所有bank收集MCE信息的过程，在这之后，会根据实际情况：（1）是否有设置panic_on_oops（2）容忍级别小于1，来决定系统是否panic。

    如果panic，会调用mce_panic，在此函数中会调用apei_write_mce函数将此时的MCE信息保存到ERST中，进而ERST会将其写到永久存储的物理介质中。