这次我们一起来看一下在GDB调试中属于比较典型的案例,因此也借这篇文章向大家阐述个人在分析Core Dump时的一些思路。
问题现象:
多台ECS连续出现夯机,并且问题集中发生在最近从经典网络迁移到VPC的实例上。注意,实际上并不仅仅有夯机现象,某些机器也会出现内核崩溃的情况。
初步定位:
首先,我们当然是需要抓取发生问题实例的core dump,发现发生问题时,CPU0上正在运行ARP缓存清理进程neigh_periodic_work:
PID: 35 TASK: ffff88023fe13ec0 CPU: 0 COMMAND: "kworker/0:1"
[exception RIP: __write_lock_failed+9]
RIP: ffffffff813275c9 RSP: ffff88023f7e3dc8 RFLAGS: 00000297
RAX: ffff88019c338000 RBX: ffff880035c89800 RCX: 000000000000000a
RDX: 0000000000000372 RSI: 000000012eeea6c0 RDI: ffff880035c8982c
RBP: ffff88023f7e3dc8 R8: ffffffff81aa7858 R9: 0001f955a06a7850
R10: 0001f955a06a7850 R11: 0000000000000000 R12: 0000000000000372
R13: ffffffff81aa7850 R14: ffff880035c89828 R15: ffff88019c339b90
CS: 0010 SS: 0018
#0 [ffff88023f7e3dd0] _raw_write_lock at ffffffff8168e7d7
#1 [ffff88023f7e3de0] neigh_periodic_work at ffffffff8157f3ac
#2 [ffff88023f7e3e20] process_one_work at ffffffff810a845b
#3 [ffff88023f7e3e68] worker_thread at ffffffff810a9296
#4 [ffff88023f7e3ec8] kthread at ffffffff810b0a4f
#5 [ffff88023f7e3f50] ret_from_fork at ffffffff81697758
而其他三个CPU的堆栈是这样的:
PID: 24680 TASK: ffff880090cc0fb0 CPU: 1 COMMAND: "java"
[exception RIP: __write_lock_failed+12]
RIP: ffffffff813275cc RSP: ffff880090c579b8 RFLAGS: 00000297
RAX: ffff880090c57fd8 RBX: ffffffff81aa7940 RCX: 0000000000000000
RDX: 000000012eedbe0e RSI: 0000000000000000 RDI: ffffffff81aa7944
RBP: ffff880090c579b8 R8: 00000000ac10050f R9: 000000000000005a
R10: 000000000001df88 R11: 000000000000005a R12: 0000000000000000
R13: 0000000000000001 R14: ffff8800360f2b00 R15: ffffffff81aa7760
CS: 0010 SS: 0018
#0 [ffff880090c579c0] _raw_write_lock_bh at ffffffff8168e870
#1 [ffff880090c579d8] __neigh_create at ffffffff815808d0
#2 [ffff880090c57a58] ip_finish_output at ffffffff815b66c5
#3 [ffff880090c57aa8] ip_output at ffffffff815b7873
#4 [ffff880090c57b08] ip_local_out_sk at ffffffff815b5531
#5 [ffff880090c57b28] ip_queue_xmit at ffffffff815b58a3
#6 [ffff880090c57b60] tcp_transmit_skb at ffffffff815cf04f
#7 [ffff880090c57bd0] tcp_write_xmit at ffffffff815cf68a
#8 [ffff880090c57c38] __tcp_push_pending_frames at ffffffff815d048e
#9 [ffff880090c57c50] tcp_push at ffffffff815bed2c
#10 [ffff880090c57c60] tcp_sendmsg at ffffffff815c25b8
#11 [ffff880090c57d28] inet_sendmsg at ffffffff815ed854
#12 [ffff880090c57d58] sock_aio_write at ffffffff81555227
#13 [ffff880090c57e20] do_sync_write at ffffffff811fe18d
#14 [ffff880090c57ef8] vfs_write at ffffffff811feaf5
#15 [ffff880090c57f38] sys_write at ffffffff811ff51f
#16 [ffff880090c57f80] system_call_fastpath at ffffffff81697809
我们可以通过如上的堆栈可以确认两者__neigh_create和 neigh_periodic_work 都在尝试取锁,但是谁是因谁是果呢?我们可以通过bt -l来确认具体的source line,对上源码之后就可以确认:
__neigh_create
…
write_lock_bh(&tbl->lock); ----》当前源码行,尝试取全局锁tbl->lock
static void neigh_periodic_work(struct work_struct *work)
{
…
write_lock_bh(&tbl->lock); ----》尝试取全局锁tbl->lock
…
for (i = 0 ; i < (1 << nht->hash_shift); i++) {
np = &nht->hash_buckets[i];
while ((n = rcu_dereference_protected(*np,
lockdep_is_held(&tbl->lock))) != NULL) {
unsigned int state;
…
write_lock(&n->lock); ----》当前源码行
…
write_unlock(&n->lock);
以此我们可以确认其他三个CPU都在尝试获取全局锁tbl->lock,而CPU0 neigh_periodic_work已经成功获取了全局锁,而正在尝试获取局部锁。因此可以确认CPU0是真正的元凶,也就是说如果CPU0成功获取了局部锁,并且释放全局锁之后,其他CPU也会正常运行。
深入分析:
接下去的问题是为何neigh_periodic_work停留在局部锁上,我们可以来尝试来理解一下neigh_periodic_work,很明显这是一个周期性会被唤醒的线程,该线程会定期释放全局列表tbl->lock,而tbl正是全局的arp缓存表的存放处。由于可能会有多个CPU同时操作该表的情况,因此内核代码为其加上了一个全局锁也就是tbl->lock。而neigh_periodic_work显然在获取全局锁之后,在操作每一个表项的时候,需要再获取针对每一个表项的局部锁,我们正是在获取局部锁的时候停住了。那么首先重要的是,我们需要看看这个表象本身是否正常:
crash> kmem -S ffff880035c89800
CACHE NAME OBJSIZE ALLOCATED TOTAL SLABS SSIZE
ffff88017fc01600 kmalloc-512 512 1262 1504 94 8k
SLAB MEMORY NODE TOTAL ALLOCATED FREE
ffffea0000d72200 ffff880035c88000 0 16 15 1
FREE / [ALLOCATED]
[ffff880035c88000]
[ffff880035c88200]
[ffff880035c88400]
[ffff880035c88600]
[ffff880035c88800]
[ffff880035c88a00]
[ffff880035c88c00]
[ffff880035c88e00]
[ffff880035c89000]
[ffff880035c89200]
[ffff880035c89400]
[ffff880035c89600]
ffff880035c89800
[ffff880035c89a00]
[ffff880035c89c00]
[ffff880035c89e00]
注:有兴趣的同学可以尝试通过反汇编加上CPU0中的寄存器来还原这个表象的内存地址。
很明显该表项对应的内存来看已经被释放了,当然此时表项数据结构中lock自然也不存在了,是无意义的数据,因此当该线程尝试去去锁时,是不会再有另外线程在释放这个不存在的锁的。自然也就会发生夯机的问题。
那么接下去的问题就是导致内存会被释放的可能原因是什么。
源码分析:
我们再来看看发生问题时候附近的源码:
write_lock(&n->lock);
state = n->nud_state;
if (state & (NUD_PERMANENT | NUD_IN_TIMER)) {
write_unlock(&n->lock);
goto next_elt;
}
if (time_before(n->used, n->confirmed))
n->used = n->confirmed;
if (atomic_read(&n->refcnt) == 1 &&
(state == NUD_FAILED ||
time_after(jiffies, n->used + NEIGH_VAR(n->parms, GC_STALETIME)))) {
*np = n->next;
n->dead = 1;
write_unlock(&n->lock); -------------》重点关注
neigh_cleanup_and_release(n);-------------》重点关注
continue;
}
write_unlock(&n->lock);
这是一种常见的同步机制,如果仅仅考虑以上两行代码,第一行我们在操作失败时释放了锁,第二部我们将内存释放,我们可以想想这样会不会产生问题。其实仅有这两行代码的最大问题是在两行之间留下了窗口,在执行这两行代码之间,如果有另外的CPU执行了类似的操作,那么他有可能赶在第二行执行之前先将内存释放(因为此时锁已经被释放,锁保护已经不存在了),那么我们在当前CPU上执行第二行时会产生不可能预料的结果。
这也就是引入n->dead = 1这一行的考虑,希望能够每次在释放之前都能够检查n->dead == 1是否成立,如果成立表明已经被释放或者正在释放中,当前执行代码已经跳过不做释放处理。那么前提有两个:
- 每次在释放锁之前都必须设置该标志位。
- 每次在释放之前必须检查该标志位。
我们仔细来阅读该版本3.10.0-514.26.2.el7.x86_64的内核代码发现这两条在某些代码段并不成立,比如:
int __neigh_event_send(struct neighbour *neigh, struct sk_buff *skb){
int rc;
bool immediate_probe = false;
write_lock_bh(&neigh->lock);
rc = 0;
if (neigh->nud_state & (NUD_CONNECTED | NUD_DELAY | NUD_PROBE))
goto out_unlock_bh;
通过比较相关代码我们可以看到在3.10.0-693.21.1.el7.x86_64已经被修复:
int __neigh_event_send(struct neighbour *neigh, struct sk_buff *skb){
int rc;
bool immediate_probe = false;
write_lock_bh(&neigh->lock);
rc = 0;
if (neigh->nud_state & (NUD_CONNECTED | NUD_DELAY | NUD_PROBE))
goto out_unlock_bh;
if (neigh->dead) ---------------> 检查标志位
goto out_dead;
建议自然就是升级内核版本。当然补充一点:其实提前释放内存的问题导致现象可能并不仅仅是夯机,更常见的一种现象是内核崩溃,因为被释放的内存包含无意义的数据,访问这些无意义的数据很可能会跳转到无效内存地址上,从而导致异常,而确实在该客户的机器中也存这样直接内核崩溃的现象,有兴趣的同学可以分析一下这种现象的core dump。