如何linux内核报告问题

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:[] ? warn_slowpath_common+0x87/0xc0
kernel:[] ? warn_slowpath_null+0x1a/0x20
kernel:[] ? rb_reserve_next_event+0x2ce/0x370
kernel:[] ? ring_buffer_lock_reserve+0xa2/0x160
kernel:[] ? trace_buffer_lock_reserve+0x2c/0x70
kernel:[] ? trace_current_buffer_lock_reserve+0x16/0x20
kernel:[] ? ftrace_raw_event_hrtimer_cancel+0x4e/0xb0
kernel:[] ? hrtimer_try_to_cancel+0xba/0xd0
kernel:[] ? do_setitimer+0xd4/0x220
kernel:[] ? alarm_setitimer+0x3a/0x60
kernel:[] ? sys_alarm+0xe/0x20
kernel:[] ? 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: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: CPU 11
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:
kernel: Pid:5492, comm: qmgr Tainted: G W ---------------- 2.6.32-220.el6.x86_64 #1 HPProLiant DL360 G7
kernel: RIP:0010:[] []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:[] ? alarm_setitimer+0x3a/0x60
kernel:[] ? sys_alarm+0xe/0x20
kernel:[] ? 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:[] ? do_setitimer+0x209/0x220
kernel:[] ? alarm_setitimer+0x3a/0x60
kernel:[] ? sys_alarm+0xe/0x20
kernel:[] ? 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