Linux内核崩溃问题排查过程总结

1.概述
某年某月某日某项目的线上分布式文件系统服务器多台linux系统kernel崩溃，严重影响了某项目对外提供服务的能力，在公司造成了不小影响。通过排查线上问题基本确定了是由于linux内核panic造成的原因，通过两个阶段的问题排查，基本上确定了linux内核panic的原因。排查问题的主要手段就是网上查找资料和根据内核错误日志分析并且构造条件重现。本文档就是对自己在整个问题排查过程中的总结。

2.第一阶段

因为刚出现问题的时候大家都比较紧急，每天加班都很晚，也制定了很多问题重现和定位原因的计划。我第一阶段连续坚持了两周分析问题原因，由于第一阶段自己所做的功能基本上全部形成了详细的分析文档，所以下面主要总结一下自己在第一阶段都采取了一些什么样的措施以及到达了什么效果。

第一阶段自己也分了几步走，当然最先想到的是重现线上的现象，所以我首先查看了线上的内核错误日志，根据日志显示主要是qmgr和master两个进程导致的内核panic（至少日志信息是这么提示的）。当然还结合当时服务器的现象，load比较高，对外不能提供服务。所以自己首先想到的就是通过写程序模拟不断发送邮件（因为qmgr和master进程都与发送邮件相关的进程），当程序运行起来的时候，自己小小的激动了一下，就是load上去了，服务器的对外服务能力变慢了（ssh登录），当时的线上接近线上现象，但是后面内核一直没有panic，哪怕频率在快，而且内核也没有什么错误信息。后面渐渐的就排除了这个原因。

因为出错的服务器都安装了分布式文件系统，大家就怀疑是由于分布式文件系统导致了内核panic，但是通过观察业务监控信息发现那个时段分布式文件系统没有什么特殊的信息，而且数据流也不是很大。不过我还是使用几台虚拟机安装了分布式文件系统，并且写了一个java程序并且不断的通过分布式文件系统客户端写入文件到分布式文件系统集群，同时也把邮件发送程序启动，尽量模拟线上的环境，跑了很多次很长时间也没有出现线上的现象，所以也没有什么更好的手段去重现线上的现象了。

由于重现现象失败了，所以只有根据内核的错误信息直接去分析原因了。分析步骤很简单，首先找到出错的错误代码，然后分析上下文相关的代码，分析的详细过程在去年的文档也体现出来了。

根据代码的分析和网上类似的bug基本上定位就是计算cpu调度的时间溢出，导致watchdog进程抛出panic错误，内核就挂起了。根据分析定位的原因，我又通过修改内核代码去构造时间溢出的条件，就是通过内核模块去修改系统调用时间的计数值，修改是成功了，可惜内核也直接死掉了。所以直接修改内核代码来重现也失败了。

后面也陆续咨询了很多公司外面熟悉内核的技术人员，他们根据我们提供的信息业给出了自己的分析，但是也没有很好的重现方法和确切的定位错误原因，而且不同的人给出的结论差异也比较大。

所以第一个阶段连续坚持跟踪这个问题2-3周的时间也没有一个确切的结果。

3.第二阶段
新的一年开始了，第一天又开始准备跟踪这个问题了。一开始也制定了简单的计划，我对自己的计划就是每天5-8点分析定位内核问题，当然也顺便学习内核相关知识。

这一次一开始自己便换了一个角度去思考问题，去年是基于单台服务器去分析内核日志错误信息，已经没有什么好的方式了。所以准备同时分析所有出错服务器的日志（幸好以前找运维要了所有出错服务器的内核日志并且保存下来了，不然怎么死的都不知道），找出他们的共同点。首先他们的共同点就是出现了trace子系统打印的警告信息“Delta way too big！…..”的信息，但是根据相关信息，这个是不会导致linux系统挂起的。而且确实我们线上的服务器并不是全部都ssh不上去，不过还是在RedHat官方网站找到类似的bug（url：

https: //access.redhat.com/knowledge/solutions/70051），并且给出了解决方案。bug信息和解决方案如下：

why kernel is throwing “Delta way too big” out with

WARNING: at kernel trace ring_buffer,c:1988 rb_reserve_next_event+0x2ce/0×370 messages

0 Issue    kernel is throwing ”Delta way too big” out with kernel oops on server

Environment（环境）

•Red Hat Enterprise Linux 6 service pack 1

Resolution（解决方案）

The warning ”Delta way too big” warning might appear on a system with unstable shed clock right after the system is resumed and tracingwas enabled during the suspend.

Since it’s not realy bug, and the unstable sched clock is working fast and reliable otherwise, We suggested to keep using the sched clock in any case and just to make note in the warning itself.or disables tracing by #echo 0 > /sys/kernel/debug/tracing/tracing_on

Root Cause（根本原因） this case was ftrace involved ftrace due to teh call to ftrace_raw_event_power_end (debugfs is mounted and ftrace loaded in this case), they are to do with problems calculating a time stamp for a ring buffer entry.
Message comes from here and appears to be indicating problems with time stability.
1966 static int
1967 rb_add_time_stamp(struct ring_buffer_per_cpu *cpu_buffer,
1968  u64 *ts, u64 *delta)
1969 {
1970    struct ring_buffer_event *event;
1971    static int once;
1972  int ret;
1973
1974 if (unlikely(*delta > (1ULL << 59) && !once++)) {
1975    int local_clock_stable = 1;
1976 #ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
1977  local_clock_stable = sched_clock_stable;
1978 #endif
1979  printk(KERN_WARNING ”Delta way too big! %llu”
1980        “ ts=%llu write stamp = %llu\n%s”,
1981      (unsigned long long)*delta,
1982    (unsigned long long)*ts,
1983    (unsigned long long)cpu_buffer->write_stamp,
1984      local_clock_stable ? ”" :
1985      “If you just came from a suspend/resume,\n”
1986      “please switch to the trace global clock:\n”
1987  ”  echo global > /sys/kernel/debug/tracing/trace_clock\n”);
1988      WARN_ON(1);

This called from rb_reserve_next_event() here.
2122 /*
2123 * Only the first commit can update the timestamp.
2124 * Yes there is a race here. If an interrupt comes in
2125 * just after the conditional and it traces too, then it
2126 * will also check the deltas. More than one timestamp may
2127 * also be made. But only the entry that did the actual
2128 * commit will be something other than zero.
2129 */
2130 if (likely(cpu_buffer->tail_page == cpu_buffer->commit_page &&
2131  rb_page_write(cpu_buffer->tail_page) ==
2132  rb_commit_index(cpu_buffer))) {
2133      u64 diff;
2134
2135      diff = ts - cpu_buffer->write_stamp;
2136
2137      /* make sure this diff is calculated here */
2138    barrier();
2139
2140 /* Did the write stamp get updated already? */

2141if (unlikely(ts < cpu_buffer->write_stamp))
2142  goto get_event;
2143
2144  delta = diff;
2145  if (unlikely(test_time_stamp(delta))) {
2146
2147      commit = rb_add_time_stamp(cpu_buffer, &ts, &delta); <—- HERE
This has to do with time stamping for ring buffer entries.

通过上面的信息可以看出，其实和我去年分析的代码和方式一模一样，只是判断原因方面我不敢确定，毕竟重现不了，只能是推测。

后面又继续分析内核中出现的另一个错误，“BUG: soft lockup – CPU#N stuck for 4278190091s! [qmgr/master:进程号]”，对上面的错误信息我做了一点点处理，CPU#后面的N是对应的一个具体的cpu编号，这个在每一台服务器是不一样的，还有就是最后中括号中的进程和进程号码不同，不过就是qmgr和master。如下表格统计：

Linux Kernel 的详细介绍：请点这里
Linux Kernel 的下载地址：请点这里

推荐阅读：