【GDB调试】Linux Core Dump分析经典案例之一

这次我们一起来看一下在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是否成立,如果成立表明已经被释放或者正在释放中,当前执行代码已经跳过不做释放处理。那么前提有两个:

 

  1. 每次在释放锁之前都必须设置该标志位。
  2. 每次在释放之前必须检查该标志位。

 

我们仔细来阅读该版本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。

上一篇:我的测试自动化框架原则设计手册(时刻更新)


下一篇:迁云工具1.5.1.5版本发布