首页 > 系统相关> > linux内核bug问题排查过程详细报告

linux内核bug问题排查过程详细报告

2021-04-16 10:52:01 作者：互联网

Linux Kernel BUG:soft lockup CPU#1 stuck分析

1.线上内核bug日志

kernel: Deltaway too big! 18428729675200069867 ts=18446743954022816244 write stamp =18014278822746377

kernel:------------[ cut here ]------------

kernel:WARNING: at kernel/trace/ring_buffer.c:1988 rb_reserve_next_event+0x2ce/0x370()(Not tainted)

kernel:Hardware name: ProLiant DL360 G7

kernel:Modules linked in: fuse ipv6 power_meter bnx2 sg microcode serio_raw iTCO_wdtiTCO_vendor_support hpilo hpwdt i7core_edac edac_core shpchp ext4 mbcache jbd2sd_mod crc_t10dif hpsa radeon ttm drm_kms_helper drm i2c_algo_bit i2c_coredm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]

kernel: Pid:5483, comm: master Not tainted 2.6.32-220.el6.x86_64 #1

kernel: CallTrace:

kernel:[<ffffffff81069b77>] ? warn_slowpath_common+0x87/0xc0

kernel:[<ffffffff81069bca>] ? warn_slowpath_null+0x1a/0x20

kernel:[<ffffffff810ea8ae>] ? rb_reserve_next_event+0x2ce/0x370

kernel:[<ffffffff810eab02>] ? ring_buffer_lock_reserve+0xa2/0x160

kernel:[<ffffffff810ec97c>] ? trace_buffer_lock_reserve+0x2c/0x70

kernel:[<ffffffff810ecb16>] ? trace_current_buffer_lock_reserve+0x16/0x20

kernel:[<ffffffff8107ae1e>] ? ftrace_raw_event_hrtimer_cancel+0x4e/0xb0

kernel:[<ffffffff81095e7a>] ? hrtimer_try_to_cancel+0xba/0xd0

kernel:[<ffffffff8106f634>] ? do_setitimer+0xd4/0x220

kernel:[<ffffffff8106f88a>] ? alarm_setitimer+0x3a/0x60

kernel:[<ffffffff8107c27e>] ? sys_alarm+0xe/0x20

kernel:[<ffffffff8100b308>] ? tracesys+0xd9/0xde

kernel: ---[end trace 4d0a1ef2e62cb1a2 ]---

abrt-dump-oops: Reported 1 kernel oopses to Abrt

kernel: BUG: softlockup - CPU#11 stuck for 4278190091s! [qmgr:5492]

kernel: CPU 11

kernel:

kernel: Pid:5492, comm: qmgr Tainted: G W ---------------- 2.6.32-220.el6.x86_64 #1 HPProLiant DL360 G7

kernel: RIP:0010:[<ffffffff8106f730>] [<ffffffff8106f730>]do_setitimer+0x1d0/0x220

kernel: RSP:0018:ffff88080a661ef8 EFLAGS: 00000286

kernel: RAX:ffff88080b175a08 RBX: ffff88080a661f18 RCX: 0000000000000000

kernel: RDX:0000000000000000 RSI: 0000000000000082 RDI: ffff88080c8c4c40

kernel: RBP:ffffffff8100bc0e R08: 0000000000000000 R09: 0099d7270e01c3f1

kernel: R10:0000000000000000 R11: 0000000000000246 R12: ffffffff810ef9a3

kernel: R13:ffff88080a661e88 R14: 0000000000000000 R15: ffff88080a65a544

kernel: FS:00007f10b245f7c0(0000) GS:ffff88083c4a0000(0000) knlGS:0000000000000000

kernel: CS:0010 DS: 0000 ES: 0000 CR0: 000000008005003b

kernel: CR2:00007ff955977380 CR3: 000000100a80b000 CR4: 00000000000006e0

kernel: DR0:0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

kernel: DR3:0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400

kernel:Process qmgr (pid: 5492, threadinfo ffff88080a660000, task ffff880809577500)

kernel: Stack:

kernel:00007f10b323def0 00007f10b248ead0 00007f10b26d0f78 00007f10b248ede0

kernel:<0> ffff88080a661f68 ffffffff8106f88a 0000000000000000 0000000000000000

kernel:<0> 000000000000014c 00000000000f423d 0000000000000000 0000000000000000

kernel: CallTrace:

kernel:[<ffffffff8106f88a>] ? alarm_setitimer+0x3a/0x60

kernel:[<ffffffff8107c27e>] ? sys_alarm+0xe/0x20

kernel:[<ffffffff8100b308>] ? tracesys+0xd9/0xde

kernel: Code:89 ef e8 74 66 02 00 83 3d 15 69 b5 00 00 75 37 49 8b 84 24 70 07 00 00 48 0508 08 00 00 66 ff 00 66 66 90 fb 66 0f 1f 44 00 00 <31> c0 e9 64 fe ff ff49 8b 84 24 68 07 00 00 48 c7 80 d0 00 00

kernel: CallTrace:

kernel:[<ffffffff8106f769>] ? do_setitimer+0x209/0x220

kernel:[<ffffffff8106f88a>] ? alarm_setitimer+0x3a/0x60

kernel:[<ffffffff8107c27e>] ? sys_alarm+0xe/0x20

kernel:[<ffffffff8100b308>] ? tracesys+0xd9/0xde

abrt-dump-oops: Reported 1 kernel oopses to Abrt

2.内核软死锁（soft lockup）bug原因分析

Soft lockup名称解释：所谓，soft lockup就是说，这个bug没有让系统彻底死机，但是若干个进程（或者kernel thread）被锁死在了某个状态（一般在内核区域），很多情况下这个是由于内核锁的使用的问题。

Linux内核对于每一个cpu都有一个监控进程，在技术界这个叫做watchdog（看门狗）。通过ps –ef | grep watchdog能够看见，进程名称大概是watchdog/X（数字：cpu逻辑编号1/2/3/4之类的）。这个进程或者线程每一秒钟运行一次，否则会睡眠和待机。这个进程运行会收集每一个cpu运行时使用数据的时间并且存放到属于每个cpu自己的内核数据结构。在内核中有很多特定的中断函数。这些中断函数会调用soft lockup计数，他会使用当前的时间戳与特定（对应的）cpu的内核数据结构中保存的时间对比，如果发现当前的时间戳比对应cpu保存的时间大于设定的阀值，他就假设监测进程或看门狗线程在一个相当可观的时间还没有执。Cpu软锁为什么会产生，是怎么产生的？如果linux内核是经过精心设计安排的CPU调度访问，那么怎么会产生cpu软死锁？那么只能说由于用户开发的或者第三方软件引入，看我们服务器内核panic的原因就是qmgr进程引起。因为每一个无限的循环都会一直有一个cpu的执行流程（qmgr进程示一个后台邮件的消息队列服务进程），并且拥有一定的优先级。Cpu调度器调度一个驱动程序来运行，如果这个驱动程序有问题并且没有被检测到，那么这个驱动程序将会暂用cpu的很长时间。根据前面的描述，看门狗进程会抓住（catch）这一点并且抛出一个软死锁（soft lockup）错误。软死锁会挂起cpu使你的系统不可用。

如果是用户空间的进程或线程引起的问题backtrace是不会有内容的，如果内核线程那么在soft lockup消息中会显示出backtrace信息。

3.根据linux内核源码分析错误

根据我们第一部分内核抛出的错误信息和call trace（linux内核的跟踪子系统）来分析产生的具体原因。

首先根据我们的centos版本安装相应的linux内核源码，具体步骤如下：

（1）下载源码的rpm包kernel-2.6.32-220.17.1.el6.src.rpm

（2）安装相应的依赖库，命令：yuminstall rpm-build redhat-rpm-config asciidoc newt-devel

（3）安装源码包：rpm -ikernel-2.6.32-220.17.1.el6.src.rpm

（4）进入建立源码的目录：cd~/rpmbuild/SPECS

（5）建立生成源码目录：rpmbuild-bp --target=`uname -m` kernel.spec

下面开始真正的根据内核bug日志分析源码：

（1）第一阶段内核错误日志分析（时间在Dec 4 14:03:34这个阶段的日志输出代码分析，其实这部分代码不会导致cpu软死锁，主要是第二阶段错误日志显示导致cpu软死锁）

我们首先通过日志定位到相关源代码：看下面日志：Dec 4 14:03:34 BP-YZH-1-xxxx kernel: WARNING: atkernel/trace/ring_buffer.c:1988 rb_reserve_next_event+0x2ce/0x370() (Not tainted)

根据日志内容我们可以很容易的定位到kernel/trace/ring_buffer.c这个文件的1988行代码如下：WARN_ON(1)。

先简单解释一下WARN_ON的作用：WARN_ON只是打印出当前栈信息，不会panic。所以会看到后面有一大堆的栈信息。这个宏定义如下：

#ifndef WARN_ON

#defineWARN_ON(condition) ({ \

int __ret_warn_on = !!(condition); \

if (unlikely(__ret_warn_on)) \

__WARN(); \

unlikely(__ret_warn_on); \

})

#endif

这个宏很简单保证传递进来的条件值为0或者1（两次逻辑非操作的结果），然后使用分支预测技术（保证执行概率大的分支紧邻上面的指令）判断是否需要调用__WARN()宏定义。如果满足条件执行了__WARN()宏定义也接着执行一条空指令;。上面调用WARN_ON宏是传递的1，所以会执行__WARN()。下面继续看一下__WARN()宏定义如下：

#define __WARN() warn_slowpath_null(__FILE__,__LINE__)

从接下来的call trace信息中我们也确实发现调用了warn_slowpath_null这个函数。通过在linux内核源代码中搜索这个函数的实现，发现在panic.c（内核恐慌时的相关功能实现）中实现如下：

voidwarn_slowpath_null(const char *file, int line)

{

warn_slowpath_common(file, line,__builtin_return_address(0),

TAINT_WARN, NULL);

}

EXPORT_SYMBOL(warn_slowpath_null);//都出这个符号，让其他模块可以使用这个函数

同样的我们看到了warn_slowpath_common这个函数，而在call trace当中这个函数在warn_slowpath_null函数之前打印出来，再次印证了这个流程是正确的。同样在panic.c这个文件中我发现了warn_slowpath_common这个函数的实现如下：

static voidwarn_slowpath_common(const char *file, int line, void *caller,

unsigned taint, struct slowpath_args *args)

{

const char *board;

printk(KERN_WARNING "------------[ cut here]------------\n");

printk(KERN_WARNING "WARNING: at %s:%d %pS()(%s)\n",

file, line, caller, print_tainted());

board = dmi_get_system_info(DMI_PRODUCT_NAME);//得到dmi系统信息

if (board)

printk(KERN_WARNING "Hardware name:%s\n", board);//通过我们的日志信息可以发现我们硬件名称是ProLiant DL360 G7

if (args)

vprintk(args->fmt, args->args);

print_modules();//打印系统模块信息

dump_stack();//dump信息输出（call trace开始）

print_oops_end_marker();//打印oops结束

add_taint(taint);

}

分析这个函数的实现不难发现我们的很多日志信息从这里开始输出，包括打印一些系统信息，就不继续深入分析了（请看代码注释，里面调用相关函数打印对应信息，通过我分析这些函数的实现和我们的日志信息完全能够对应，其中dump_stack是与cpu体系结构相关的，我们的服务器应该是属于x86体系）。这里在继续分析一下dump_stack函数的实现，因为这个是与cpu体系结构相关的，而且这个函数直接反应出导致内核panic的相关进程。这个函数实现如下：

* The architecture-independent dump_stackgenerator

void dump_stack(void)

{

unsigned long stack;

printk("Pid: %d, comm: %.20s %s %s %.*s\n",

current->pid, current->comm,print_tainted(),

init_utsname()->release,

(int)strcspn(init_utsname()->version, ""),

init_utsname()->version);

show_trace(NULL, NULL, &stack);

}

EXPORT_SYMBOL(dump_stack);

通过我们的日志信息（Dec 4 14:03:34 BP-YZH-1-xxxx kernel: Pid: 5483, comm: master Nottainted 2.6.32-220.el6.x86_64 #1）很容易看出来，这个进程首先是由于master进程导致的，进程id是5483.这个函数的最后一行代码调用show_trace函数打印call trace信息，这个函数实现如下：

void show_trace(structtask_struct *task, struct pt_regs *regs,

unsigned long *stack)

{

show_trace_log_lvl(task, regs, stack, "");

}

这个函数继续调用show_trace_log_lvl函数，如下：

void show_trace_log_lvl(structtask_struct *task, struct pt_regs *regs,

unsigned long *stack, char *log_lvl)

{

printk("%sCall Trace:\n", log_lvl);

dump_trace(task, regs, stack, &print_trace_ops,log_lvl);

}

这个函数打印出我们日志中的Call Trace信息，然后继续调用dump_trace函数（x86-64相关的体系结构，也就是64位的，还有一个32位的相应实现），如下：

* x86-64 can have up to three kernel stacks:

* process stack

* interrupt stack

* severe exception (double fault, nmi, stackfault, debug, mce) hardware stack

void dump_trace(structtask_struct *task, struct pt_regs *regs,

unsigned long *stack,

const struct stacktrace_ops *ops, void *data)

{

const unsigned cpu = get_cpu();

unsigned long *irq_stack_end =

(unsigned long *)per_cpu(irq_stack_ptr, cpu);

unsigned used = 0;

struct thread_info *tinfo;

int graph = 0;

unsigned long bp;

if (!task)

task = current;

if (!stack) {

unsigned long dummy;

stack = &dummy;

if (task && task != current)

stack = (unsigned long*)task->thread.sp;

}

bp = stack_frame(task, regs);

* Print function callentries in all stacks, starting at the

* current stackaddress. If the stacks consist of nested

* exceptions

tinfo = task_thread_info(task);

for (;;) {

char *id;

unsigned long *estack_end;

estack_end = in_exception_stack(cpu, (unsignedlong)stack,

&used,&id);

if (estack_end) {

if (ops->stack(data, id) < 0)

break;

bp = ops->walk_stack(tinfo, stack, bp,ops,

data, estack_end, &graph);

ops->stack(data,"<EOE>");

*We link to the next stack via the

*second-to-last pointer (index -2 to end) in the

*exception stack:

stack = (unsigned long *) estack_end[-2];

continue;

}

if (irq_stack_end) {

unsigned long *irq_stack;

irq_stack = irq_stack_end -

(IRQ_STACK_SIZE - 64) /sizeof(*irq_stack);

if (in_irq_stack(stack, irq_stack,irq_stack_end)) {

if (ops->stack(data,"IRQ") < 0)

break;

bp = ops->walk_stack(tinfo,stack, bp,

ops, data,irq_stack_end, &graph);

* We link to the next stack (which would be

* the process stack normally) the last

* pointer (index -1 to end) in the IRQ stack:

stack = (unsigned long *)(irq_stack_end[-1]);

bp = fixup_bp_irq_link(bp,stack, irq_stack,

irq_stack_end);

irq_stack_end = NULL;

ops->stack(data,"EOI");

continue;

}

break;

}

* This handles theprocess stack:

bp = ops->walk_stack(tinfo, stack, bp, ops, data, NULL,&graph);

put_cpu();

}

EXPORT_SYMBOL(dump_trace);

通过这个函数的注释我们可以清楚的知道这个函数打印很多信息，包括进程堆栈信息、中断堆栈信息以及一些服务异常的硬件堆栈信息（如双重故障，NMI，堆栈错误，调试，MCE）。

通过上面这些分析只想说明一点，整个流程是没有问题的。到目前为止只有第一行日志信息还没有找到输出的地址，其实看源码很容易就看出来了，就在WARN_ON宏的上一行代码就是了，代码如下：

printk(KERN_WARNING "Delta way toobig! %llu"

" ts=%llu write stamp =%llu\n%s",

(unsigned long long)*delta,

(unsigned long long)*ts,

(unsigned long long)cpu_buffer->write_stamp,

local_clock_stable ? "" :

"If you just came from asuspend/resume,\n"

"please switch to the trace globalclock:\n"

" echo global > /sys/kernel/debug/tracing/trace_clock\n");

Printk函数的作用相当于printf，只是这个是专门用于内核的（有一些特殊实现）。通过一句代码我们也可以发现local_clock_stable是为0，因为没有打印最后那一点信息出来。到这里为止基本把第一阶段出现内核错误和bug的代码全部理解清楚了（日志时间为：Dec 4 14:03:34这个时间输出的），后面附件具体分析导致这个原因代码的原因。

（2）第二阶段（时间在Dec 4 14:03:41，与第一阶段只相差了几秒钟，应该还是存在一定的关联）内核错误日志输出代码分析，这部分日志输出显示了导致了cpu软死锁。

根据第二部分关于可能产生软死锁原因的分析，我们能够知道，这个软死锁最终是由watchdog程序抛出的。对第二阶段的第一条输出日志，我通过搜索找到在文件kernel/watchdog.c中的296行找到。这行代码所在的函数是watchdog_timer_fn，这个函数定义如下：

/* watchdog kickerfunctions */

static enumhrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)

{

unsigned long touch_ts = __get_cpu_var(watchdog_touch_ts);

struct pt_regs *regs = get_irq_regs();

int duration;

/* kick the hardlockup detector */

watchdog_interrupt_count();

/* kick the softlockup detector */

wake_up_process(__get_cpu_var(softlockup_watchdog));

/* .. and repeat */

hrtimer_forward_now(hrtimer,ns_to_ktime(get_sample_period()));

if (touch_ts == 0) {

if(unlikely(__get_cpu_var(softlockup_touch_sync))) {

/* If the time stamp was touchedatomically

*make sure the scheduler tick is up to date. */

__get_cpu_var(softlockup_touch_sync) =false;

sched_clock_tick();

}

__touch_watchdog();

return HRTIMER_RESTART;

}

/* check for a softlockup

* This is done bymaking sure a high priority task is

* being scheduled. The task touches the watchdog to

* indicate it isgetting cpu time. If it hasn't then

* this is a goodindication some task is hogging the cpu

duration = is_softlockup(touch_ts);

if (unlikely(duration)) {

/* only warn once */

if (__get_cpu_var(soft_watchdog_warn) == true)

return HRTIMER_RESTART;

printk(KERN_ERR "BUG: soft lockup - CPU#%dstuck for %us! [%s:%d]\n",

smp_processor_id(), duration,

current->comm, task_pid_nr(current));

print_modules();

print_irqtrace_events(current);

if (regs)

show_regs(regs);

else

dump_stack();

if (softlockup_panic)

panic("softlockup: hungtasks");

__get_cpu_var(soft_watchdog_warn) = true;

} else

__get_cpu_var(soft_watchdog_warn) = false;

return HRTIMER_RESTART;

}

下面首先需要分析一下什么情况下会调用这个函数并且导致cpu软死锁，根据第二部分cpu软死锁产生原因的分析，每一个cpu都会启动一个对应的watchdog线程来监控cpu的执行状态，创建watchdog线程是在使能watchdog功能的时候，在函数watchdog_enable里面实现，代码如下：

static intwatchdog_enable(int cpu)

{

struct task_struct *p = per_cpu(softlockup_watchdog, cpu);//保存每一个cpu的私有数据

int err = 0;

/* enable the perf event */

err = watchdog_nmi_enable(cpu);

/* Regardless of err above, fall through and startsoftlockup */

/* create the watchdog thread */

if (!p) {

p = kthread_create(watchdog, (void *)(unsignedlong)cpu, "watchdog/%d", cpu);

if (IS_ERR(p)) {

printk(KERN_ERR "softlockup watchdogfor %i failed\n", cpu);

if (!err)

/* if hardlockup hasn't alreadyset this */

err = PTR_ERR(p);

goto out;

}

kthread_bind(p, cpu);

per_cpu(watchdog_touch_ts, cpu) = 0;

per_cpu(softlockup_watchdog, cpu) = p;

wake_up_process(p);

}

out:

return err;

}

从上面这个watchdog使能函数可以看出，每一个cpu的watchdog监控线程的入口函数是watchdog函数，还注册了一个softlockup软死锁响应函数。下面开始从watchdog函数继续开始分析，代码如下：

/* The watchdog thread -touches the timestamp. */

static int watchdog(void*unused)

{

struct sched_param param = { .sched_priority = MAX_RT_PRIO-1};

struct hrtimer *hrtimer = &__raw_get_cpu_var(watchdog_hrtimer);

sched_setscheduler(current, SCHED_FIFO, &param);

/* initialize timestamp */

__touch_watchdog();

/* kick off the timer for the hardlockup detector */

/* done here because hrtimer_start can only pin tosmp_processor_id() */

hrtimer_start(hrtimer, ns_to_ktime(get_sample_period()),

HRTIMER_MODE_REL_PINNED);

set_current_state(TASK_INTERRUPTIBLE);

/* Run briefly once per second to reset the softlockuptimestamp.

* If this getsdelayed for more than 60 seconds then the

* debug-printouttriggers in watchdog_timer_fn().*/

while (!kthread_should_stop()) {

__touch_watchdog();

schedule();

if (kthread_should_stop())

break;

set_current_state(TASK_INTERRUPTIBLE);

}

__set_current_state(TASK_RUNNING);

return 0;

}

这个函数首先设置watchdog线程的cpu的调度策略为FIFO（先来先服务），并且优先级最低，然后初始化一个时间戳，设置当前的cpu状态为可中断的状态。然后就进入while循环了，通过while循环上面的注释我们可以清楚的知道每一秒钟都会重新设置softlockup的时间戳，如果超过60秒钟那么就会触发debug信息被打印，打印信息是在函数watchdog_timer_fn里面，这个函数是在watchdog模块初始化的时候注册的，每一个模块加载最先执行的都是模块初始化函数，当然卸载模块的时候也有相应的资源清理函数。

到这里为止我们知道了如果要打印出我们服务器内核的错误信息就必须得满足一个条件，就是已经超过60秒钟没有重新设置softlockup的时间戳了（每一，秒钟重新设置softlockup的时间戳，有一个比较通俗的说法叫做喂狗，因为上面的watchdog程序也俗称看门狗程序，cpu就是通过这种方式来检测cpu是否运行正常的，已经超过60秒钟没有喂狗了，那么狗肯定饿了，也就是cpu处于饥饿状态，浪费了cpu的时间了，最大的可能就是cpu产生了软死锁）。这里就不详细分析cpu调度相关的功能了，还是继续分析产生这种bug的原因。下面最主要的就是分析为什么超过60秒钟没有喂狗（重新设置softlockup时间戳）了。分析这个应该需要结合第一阶段的错误日志分析，第一阶段也是由于计算时间差值大于了一个设定的时间。

我们还是先接着上面，分析一下日志的输出是否和我们分析的代码能够对应上吧。最后就是通过call trace分析原因。

上面我们已经分析到了函数watchdog_timer_fn打印debug信息的地方了，这个函数的在前面已经粘贴出来了，我们结合我们的错误日志分析一下对应的输出内核，通过函数的分析下面这句代码就是打印我们第二阶段错误日志信息的第一条：

printk(KERN_ERR"BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",

smp_processor_id(), duration,

current->comm,task_pid_nr(current));

打印的对应日志信息：Dec 4 14:03:41BP-YZH-1-xxxx kernel: BUG: soft lockup - CPU#11 stuck for 4278190091s![qmgr:5492]

而输出这一条的条件就是linux内核检测出了已经存在软死锁（通过前面if条件判断的代码以及前面的代码注释都可以说明这一点），通过这条日志信息我们可以看到cpu的逻辑编号、进程名称和进程id（通过我们的日志信息可以看出分别是11、qmgr进程、进程id是5492）。我们在看看一个更重要的值，这个值就是决定了是否产生了软死锁，这个值就是duration，这里显示是4278190091秒。下面详细分析一下这个值是怎么被计算出来的，通过代码发现是通过下面这个函数计算出来的：

staticint is_softlockup(unsigned long touch_ts)

{

unsignedlong now = get_timestamp(smp_processor_id());

/*Warn about unreasonable delays: */

if(time_after(now, touch_ts + softlockup_thresh))

returnnow - touch_ts;

return0;

}

首先这个函数得到一个对应cpu现在的时间戳，具体怎么详细计算出来的就不分析了，反正与cpu的平率有关系，通过ns换算成为秒钟（2^30ns=1.074s，然后通过cpu_clock(this_cpu) >> 30LL;这句代码计算出来的）。接着通过调用time_after函数判断现在的时间戳now与上一次喂狗的时间戳加上softlockup_thresh（60）的先后关系，也就是判断是不是有超过60秒钟没有喂狗了，如果是就会返回一个现在的时间戳减去上一次喂狗的时间戳，如果没有就会返回0。根据我们的日志信息，很明显已经超过了，所以返回值不为0，就导致了软死锁被检测到。

后面接着打印了linux内核加载了的相关模块信息，然后打印中断trace的事件信息，一直跟踪下去，发现和我们打印的内核bug信息完全符合。

下面开始分析一下call trace，不管是第一阶段的日志还是第二阶段的日志堆栈最上层的函数都是tracesys，说明这些信息都是在trace子系统中发生的，至少说明当时都处于trace子系统的运行。其实tracesys是用汇编实现的，主要用于跟踪系统调用的功能。第二阶段的call trace基本是没有什么信息，分析不出什么效果。有一点需要说明一下，第一阶段的日志打印的信息显示是master进程，第二阶段显示是qmgr进程。在centos上master进程是qmgr进程的父进程。下面看第一阶段日志的call trace信息，如下（去掉了公共前缀信息）：

Call Trace:

[<ffffffff81069b77>]? warn_slowpath_common+0x87/0xc0

[<ffffffff81069bca>]? warn_slowpath_null+0x1a/0x20

[<ffffffff810ea8ae>]? rb_reserve_next_event+0x2ce/0x370

[<ffffffff810eab02>]? ring_buffer_lock_reserve+0xa2/0x160

[<ffffffff810ec97c>]? trace_buffer_lock_reserve+0x2c/0x70

[<ffffffff810ecb16>]? trace_current_buffer_lock_reserve+0x16/0x20

[<ffffffff8107ae1e>]? ftrace_raw_event_hrtimer_cancel+0x4e/0xb0

[<ffffffff81095e7a>]? hrtimer_try_to_cancel+0xba/0xd0

[<ffffffff8106f634>]? do_setitimer+0xd4/0x220

[<ffffffff8106f88a>]? alarm_setitimer+0x3a/0x60

[<ffffffff8107c27e>]? sys_alarm+0xe/0x20

[<ffffffff8100b308>]? tracesys+0xd9/0xde

我们直接从trace_current_buffer_lock_reserve这个函数看是吧，前面有两个函数分别是尝试停用计时器（hrtimer_try_to_cancel）和取消跟踪调试的事件计时器（ftrace_raw_event_hrtimer_cancel），在前面几个函数在trace子系统触发的时候都会被调用（跟踪一个系统调用）。trace_current_buffer_lock_reserve这个函数最终根据call trace会调用rb_reserve_next_event函数。这个函数实现如下：

static struct ring_buffer_event * rb_reserve_next_event(structring_buffer *buffer,

struct ring_buffer_per_cpu *cpu_buffer, unsignedlong length)

{

structring_buffer_event *event;

u64 ts, delta =0;

int commit = 0;

int nr_loops =0;

rb_start_commit(cpu_buffer);

#ifdef CONFIG_RING_BUFFER_ALLOW_SWAP

* Due to the ability to swap a cpu buffer froma buffer

* it is possible it was swapped before wecommitted.

* (committing stops a swap). We check for ithere and

* if it happened, we have to fail the write.

barrier();

if(unlikely(ACCESS_ONCE(cpu_buffer->buffer) != buffer)) {

local_dec(&cpu_buffer->committing);

local_dec(&cpu_buffer->commits);

returnNULL;

}

#endif

length =rb_calculate_event_length(length);

again:

* We allow for interrupts to reenter here anddo a trace.

* If one does, it will cause this originalcode to loop

* back here. Even with heavy interruptshappening, this

* should only happen a few times in a row. Ifthis happens

* 1000 times in a row, there must be either aninterrupt

* storm or we have something buggy.

* Bail!

if(RB_WARN_ON(cpu_buffer, ++nr_loops > 1000))

gotoout_fail;

ts =rb_time_stamp(cpu_buffer->buffer);

* Only the first commit can update thetimestamp.

* Yes there is a race here. If an interruptcomes in

* just after the conditional and it tracestoo, then it

* will also check the deltas. More than onetimestamp may

* also be made. But only the entry that didthe actual

* commit will be something other than zero.

if(likely(cpu_buffer->tail_page == cpu_buffer->commit_page &&

rb_page_write(cpu_buffer->tail_page) ==

rb_commit_index(cpu_buffer))) {

u64diff;

diff= ts - cpu_buffer->write_stamp;

/*make sure this diff is calculated here */

barrier();

/*Did the write stamp get updated already? */

if(unlikely(ts < cpu_buffer->write_stamp))

gotoget_event;

delta= diff;

if(unlikely(test_time_stamp(delta))) {

commit= rb_add_time_stamp(cpu_buffer, &ts, &delta);

if(commit == -EBUSY)

gotoout_fail;

if(commit == -EAGAIN)

gotoagain;

RB_WARN_ON(cpu_buffer,commit < 0);

}

get_event:

event =__rb_reserve_next(cpu_buffer, 0, length, &ts);

if(unlikely(PTR_ERR(event) == -EAGAIN))

gotoagain;

if (!event)

gotoout_fail;

if(!rb_event_is_commit(cpu_buffer, event))

delta = 0;

event->time_delta= delta;

return event;

out_fail:

rb_end_commit(cpu_buffer);

return NULL;

}

我们首先看一下这个函数的参数：其中有两个比较复杂和重要的结构体ring_buffer_per_cpu和ring_buffer，分析这两个结构体主要是为了后面的函数内部分析做一个准备。我们先看看ring_buffer结构体（简称为RB结构体）的定义，如下：

struct ring_buffer {

unsigned pages; /*RB中的页面数*/

unsigned flags; /*RB的标志,目前只有RB_FL_OVERWRITE可用*/

int cpus; /*ring buffer中包含的cpu个数*/

atomic_t record_disabled; /*整个ring buffer的禁用标志,用原子操作了防止竞争*/

cpumask_var_t cpumask; /* cpu位图*/

struct lock_class_key *reader_lock_key;/*读锁关键字*/

struct mutex mutex; /*RB访问锁*/

structring_buffer_per_cpu **buffers; /*CPU的缓存区页面,每个CPU对应一项*/

#ifdef CONFIG_HOTPLUG_CPU

structnotifier_block cpu_notify; /*多CPU情况下的cpu hotplug 通知链表*/

#endif

u64 (*clock)(void); /*RB所用的时间,用来计数时间戳*/

}

在RB的操作中,我们可以禁止全局的RB操作，例如，完全禁用掉Trace功能后，整个RB都是不允许再操做的，这时，就可以将原子变量record_disabled 加1。相反的，如果启用的话,将其减1即可。只有当record_disabled的值等于0时，才允许操作RB。

同时，有些时候,要对RB的一些数据进行更新，比如，我要重新设置一下RB的缓存区大小，这都需要串行操作，因此，在ring_buffer结构中有mutex成员，用来避免这些更改RB的操作的竞争。

ring_buffer_per_cpu定义如下：

struct ring_buffer_per_cpu {

int cpu; /*该cpu buffer所在的CPU*/

structring_buffer *buffer; /*cpu buffer所属的RB*/

/*读锁,用了避免读者的操行操作,有时在

*写者切换页面的时候,也需要持有此锁*/

spinlock_t reader_lock; /* serialize readers */

raw_spinlock_t lock;

structlock_class_key lock_key;

structlist_head pages; /*cpu buffer的页面链表*/

structbuffer_page *head_page; /* read fromhead *//*起始读位置*/

structbuffer_page *tail_page; /* write totail *//*写位置*/

/*提交位置,只有当被写的页面提交过后才允许被读*/

structbuffer_page *commit_page; /* committed pages */

structbuffer_page *reader_page; /*reader页面, 用来交换读页面*/

unsigned long nmi_dropped;

unsigned long commit_overrun;

unsigned long overrun;

unsigned long read;

local_t entries;

u64 write_stamp; /*最新的页面commit时间*/

u64 read_stamp; /*最新的页面read时间*/

atomic_t record_disabled; /*cpu buffer的禁用启用标志*/

}

首先，对每一个cpu的操作限制是由ring_buffer_per_cpu->record_disabled来实现的。同ring_buffer一样，禁用加1，启用减1。

我们也可以看到，每个cpu都有一系列的页面，这样页面都链入在pages中。

该页面的结构如下:

struct buffer_page {

struct list_headlist; /* list of buffer pages *//*用来形成链表*/

local_t write; /* index for next write *//*写的位置*/

unsigned read; /* index for next read *//*读的位置*/

local_t entries; /* entries on this page *//*页面中有多少项数据*/

structbuffer_data_page *page; /* Actual datapage */

};

具体的缓存区是由structbuffer_data_page指向的,实际上,它是具体页面的管理头部,结构如下:

struct buffer_data_page {

u64 time_stamp; /* page time stamp *//*页面第一次被写时的时间戳*/

local_t commit; /* write committed index */ /*提交的位置*/

unsigned char data[]; /* data of buffer page *//*用来存放数据的缓存区*/

};

把所有基本的结构体解析清楚以后我们就可以正在分析这个函数了，代码已经在前面写出来了。函数里面首先定义了一个ring_buffer_event结构体的变量，先看一下这个结构体的定义如下：

/* Don't refer to this struct directly, use functions below.*/

struct ring_buffer_event {

kmemcheck_bitfield_begin(bitfield);//具体作用参考Documentation / kmemcheck.txt

u32 type_len:5, time_delta:27;

kmemcheck_bitfield_end(bitfield);

u32 array[];

};

这个结构体注释提醒不要直接使用，只能在函数体里面使用，这里是在函数体里面定义和使用的。里面加入了动态内存检测的字段kmemcheck，这个特性类似用户态动态内存检测工具valgrind，只是实现上有很大的区别，而且这个主要是用于内核动态内存检测技术。继续上面函数的分析，然后定义了一些需要用到的变量。继续就开始调用函数rb_start_commit，函数代码如下：

static void rb_start_commit(struct ring_buffer_per_cpu*cpu_buffer)

{

local_inc(&cpu_buffer->committing);

local_inc(&cpu_buffer->commits);

}

分别以cpu_buffer的committing和commits字段为参数调用local_inc函数，一直跟踪下去最终会调用如下函数：

/**

* atomic_add - addinteger to atomic variable

* @i: integer value toadd

* @v: pointer of typeatomic_t

* Atomically adds @ito @v.

static inline void atomic_add(int i, atomic_t *v)

{

asmvolatile(LOCK_PREFIX "addl %1,%0"

: "=m" (v->counter)

: "ir" (i), "m"(v->counter));

}

其实最终就是使用汇编实现一个长整型变量的原子加（addl）1操作。接下来是一段需要使能了RB交换swap功能（和虚拟内存交换，linux系统称为交换区，有硬盘充当）。接下来调用函数rb_calculate_event_length计算事件长度。继续我们就会看到一大段英文注释，大体上是说，在调用这个函数之前禁止了抢占，中断和NMI在这里存在着竞争，因此在下面的运行中,随时都会被中断/NMI所抢占。由于在从struct ring_buffer_per_cpu中取页面的时候，会有当前页面空间不足，需要前进一个页面的情况.每次前进一个页面都会跳转到again，此时nr_loops都会增加1，如果在一次请求中,这样的情况出现了1000次，说明中断抢占的次数太多了，很可能是由于中断风暴(interrupte storm)或者是bug造成的。下面就是调用宏函数RB_WARN_ON，如果超过1000次就打印相关call trace信息，根据我们的服务器日志这里没有打印。继续就是调用函数ring_buffer_time_stamp取当前的时间戳并赋值给ts临时变量。下面又是一大段英文注释，意思是只有第一次处于提交状态的请求才能够更新cpu_buffer->write_stamp（cpu的写时间戳），这里存在着竞争。下面详细分析这里代码执行的情况，因为涉及到delta计算的问题，这也是导致我们服务器bug的最基本和开始的原因。

从这里的if判断可以看到，只有在fistcommit的时候才会计算delta，其它的情况下，会获取下一个event。我们来思考一下，为什么在确认了是fist commit，进入到了if，还需要进行:

if (unlikely(ts < cpu_buffer->write_stamp))

gotoget_event;

的判断呢？这个delta到底是用来做什么的呢?它为什么要用这样的判断方式呢？我们在之前说过，在ring_buffer_per_cpu中的每一块数据都带有一个event的头部，即:

struct ring_buffer_event {

u32 type:2, len:3, time_delta:27;

u32 array[];

};

它里面有一个time_delta的成员占27位。在每一个页面的头部，即Structbuffer_data_page里面也有一个时间戳，即：

struct buffer_data_page {

u64 time_stamp; /* page time stamp */

local_t commit; /* write commited index */

unsigned char data[]; /* data of buffer page */

}

那这几个时间戳有什么样的关联呢？在ring_buffer_per_cpu中有一个timestamp，它表示最近commit时的时间戳。每次切换进一个新页面时，该页面对应的：

buffer_data_page->time_stamp会记录当前的时间戳。即buffer_date_page->time_stamp记录页面被切换成写页面时的时间戳。而ring_buffer_event->time_delta表示当前时间和上一次commit时间即ring_buffer_per_cpu->time_stamp的差值。

综上所述,存在以下关系：

页面中的第一个event，event1在进行写操作时的时间戳为：

buffer_data_page->time_stamp+ ring_buffer_event1->time_delta.

第二个event,event2在进行写操作时的时间戳为：

buffer_data_page->time_stamp+ring_buffer_event1->time_delta+

ring_buffer_event2->time_delta.

依次类推，不过有种情况是特别的,即RINGBUF_TYPE_TIME_EXTEND类型的EVENT，它是为了有时delta时间超过27位时，扩展了一个32位用来存放的时间戳。这也就是上面代码中的if (test_time_stamp(delta))。另外需要注意,这里的返回值commit，只有在fistcommit的时候才会为1。

分析到这里我们发现计算出来的delta值超过了设定的阀值，所以打印处理debug信息，我们分析一下打印出来的几个时间值（应该是系统节拍值），日志如下：

Delta way too big! 18428729675200069867ts=18446743954022816244 write stamp = 18014278822746377

通过上面这条日志我们可以确定此时的delta=18428729675200069867，ts=18446743954022816244write stamp = 18014278822746377（cpu里面记录的上次写入的值）。这三个值有如下关系：diff = ts - cpu_buffer->write_stamp;通过计算器计算确实满足。那下面在看看ts是怎么计算出来的，他是计算linux服务器冲启动到现在的节拍数，和设置的HZ有关系，最终还是调用sched_clock函数计算所得，这个函数代码实现如下：

unsigned long long __attribute__((weak)) sched_clock(void)

{

//因为内核在启动的时候就将jiffies的值初始化为INITIAL_JIFFIES（-300*HZ）

return(unsigned long long)(jiffies - INITIAL_JIFFIES)

*(NSEC_PER_SEC / HZ);

}

以上函数是cpu调度的节拍数计算方式，全局变量jiffies用来记录从系统启动以来产生的节拍的总数，启动时，内核将该变量初始化为INITIAL_JIFFIES，网上有的说法又是初始化为0，为了验证到底初始化为多少我们使用一个内核模块在启动的时候就把这个值打印出来看一看就清楚，通过测试初始化值确实是INITIAL_JIFFIES。此后，每次时钟中断处理程序都会增加该变量的值。一秒内时钟中断的次数等于HZ，所以jiffies一秒内增加的值也就是HZ。系统运行时间以秒为单位，等于jiffies/HZ。注意，jiffies类型为无符号长整型(unsigned long)，其他任何类型存放它都不正确。将以秒为单位的时间转化为jiffies：seconds * Hz。将jiffies转化为以秒为单位的时间：jiffies / HZ。HZ的值在param.h中设置为100，那么通过日志中打印出来的ts值（单位是纳秒）计算服务器已经启动了多少天：18446743954022816244/1000000000/24/60/60=213504（天），这个值明显不对，那我们在计算一下上一次cpu记录的写入值（write stamp = 18014278822746377）是否正确？同样的计算方式如下：18014278822746377/1000000000/24/60/60=208（天）这个值还算比较正确，就是上一次写入对应的值已经是208天以前的时候。

INITIAL_JIFFIES的宏定义如下：

#defineINITIAL_JIFFIES ((unsigned long)(unsigned int) (-300*HZ))

SEC_PER_SEC是每一秒钟的纳秒数（1000000000）。

于是整个表达式计算为：系统当前运行的节拍值4294937296（INITIAL_JIFFIES计算所得），然后再除以1000000000/100=10000000。从我们的日志中可以看出当前计算出来的值是ts：18446743954022816244。根据这个值我们可以反推出jiffies-INITIAL_JIFFIES=1844674395402。这个值明显不对，在看cpu软死锁产生的一条日志信息如下：

BUG: soft lockup- CPU#11 stuck for 4278190091s! [qmgr:5492]

通过这条日子好也可以看出这个时间4278190091s完全不正常。造成这种不正常的原因可能是内存破坏造成的。

新发现：在使用内核模块修改jiffies值的时候，直接导致了centos产生了cpu softlockup错误，而且从内核打印出的错误信息可以看出最后加载的模块就是我写的那个测试模块，对比线上服务器崩溃的内核日志查看最后加载的内核模块是scsi_scan_wait。由此可以推断可能是由于scsi_scan_wait这个内核模块导致了qmgr进程产生了cpu软死锁，也就是导致了qmgr已经超过了60秒没有得到中断响应了。

4.结论

由于一直不能重现这个错误，所以一直没有排查出问题的正在原因，目前还是继续排查，想办法还原错误。如果有哪位以前遇到过同样的问题并且得到了解决麻烦告知一声，非常感谢！

标签：kernel,函数,bug,buffer,stack,内核,linux,watchdog,cpu
来源： https://blog.51cto.com/u_15169172/2710291