现在的位置: 首页 > 综合 > 正文

futex pthread_mutex_lock 相关故障排查

2013年01月16日 ⁄ 综合 ⁄ 共 6178字 ⁄ 字号 评论关闭

status显示调度次数没有变化(与sched_debug吻合),然而/proc/1400/stat看到的用户态内核态时间却一直在增加,这是否矛盾了?

分析do_task_stat的实现,如果函数参数whole为1的话,则计算整个线程组的运行时间。

由于proc/pid/stat和/proc/pid/tasks/tid/stat分别给do_task_stat传递1和0,也就是说,要观察一个线程的运行时间,还是要通过后者。通过后者查看1400的用户态和内核态时间没有变化。

下面继续来看1486和1400线程在做什么。

 

~ # cat /proc/1486/stack

[<98000000022d6e7c>] schedule+0xad0/0xdd8

[<980000000205299c>] do_softirq+0x84/0xb8

[<9800000002052f38>] irq_exit+0x6c/0x7c

[<980000000200b940>] ret_from_irq+0x0/0x4

[<9800000002074c00>] futex_wait+0x55c/0x58c

 

~ # cat /proc/1400/stack

[<98000000022d6e7c>] schedule+0xad0/0xdd8

[<98000000022d8f88>] rt_mutex_slowlock+0x314/0x3b0

[<9800000002040ffc>] sched_setaffinity+0x38/0x2fc

[<9800000002041348>] sys_sched_setaffinity+0x88/0xa0

[<980000000201a534>] handle_sys64+0x54/0x70


1486的切换栈在futex_wait中不停变化,而1400的切换栈不变,一直保持在设置CPU亲和力处。因此可以推断,1486在用户态不停的调futex,而1400在设置亲和力的时候在内核态被抢占。

2.2 用户栈原始数据分析

为了搞清为何1486不停的在用户态调用futex,于是在内核添加代码,故障复现时,打印1486的用户栈。

由于1486不释放CPU,因此通过/proc/pid/stack看到的是上次切换的现场回溯,如果要查看1486当前在做什么,就要在时钟中断里添加回溯。另外由于1486也有可能是在内核态被中断,因此要获取用户态信息,使用task_pt_regs获取第一次切换内核栈时保存的现场。

 

复现时打印信息如下:

Call Trace:

[<9800000002013cb4>] dump_stack+0x8/0x44

[<980000000205a4fc>] update_process_times+0x80/0x128

[<9800000002005184>] xlr_main_timer_interrupt+0xd0/0xec

[<980000000208ac90>] handle_IRQ_event+0x7c/0x178

[<980000000208ae84>] __do_IRQ+0xf8/0x21c

[<9800000002003a60>] plat_irq_dispatch+0x410/0x42c

[<980000000200b940>] ret_from_irq+0x0/0x4

[<9800000002073668>] get_futex_key+0x20/0x180

[<9800000002074934>] futex_wait+0xb0/0x58c

[<9800000002075464>] do_futex+0xb4/0x1dcc

[<98000000020772cc>] sys_futex+0x150/0x17c

[<980000000201a6b4>] handle_sys64+0x54/0x70

 

current process:[1486]-[0x12101f79c]

dump user stack:

000000800018a850:0000000000000000 0000000000000000 ffffffdbfffeffff fffeffedff7fffff

000000800018a870:fffcafffffffffff ffdffbffbfbf7fff ffffffeffff7ffef ffffefaffbffffff

000000800018a890:fffffffefffffbfb ffffffffffffffff fffffbffffffffff ffffd7ffffffdffe

000000800018a8b0:ffffdffffffbfff7 fffffffffff7efff ff7fffefffd5ffff fffefffefdfeffdf

000000800018a8d0:f7fdffffcffdffff ffffffffff7fffbf 0000000121017c7c 000000800018a860

000000800018a8f0:000000012408b4b0 000000800018b0c0 0000000121017bf8 000000800018aa10

000000800018a910:00000000007d0f00 0000000000000001 0000005555f7fdf0 00000001200ee4c0

000000800018a930:0000005555f7fde0 000000012403a4c0 ffffffffddfef7ff fff77fdfbfffffee

000000800018a950:ff7feff7ffffffff fb7ffde6bbff7fff fffffbffdf7fffff ffffffb7fffeefff

000000800018a970:ffffff7fffffffff ffffdfd5bfcfffbf fffdffffffbe7dff 00000000dffffefd

000000800018a990:0000000000000000 0000000000000000 ffffff7ffff7ffbf dfffff7d7ffffffd

000000800018a9b0:000000800018b0c0 ffff7f3f7fff7fef 000000012408b4b0 000000800018b0c0

000000800018a9d0:0000000121017bf8 000000012403a4c0 000000012107432c ffffbffffff7ffaf

000000800018a9f0:0000000121017bf8 000000800018b0c0 00000000007d0f00 fffbbff5fffdffff

 

 

epc的值显示1486位于__lll_lock_wait

抽取用户栈从高到低的有效值,对照反汇编得到的结果为:

1) Entry

2) __thread_start :  move    a0,v0     

3) start_thread 

4)bnez    v0,121017cb0 <start_thread+0xb8>

从上面的结果我们可以大致猜测出,1486在刚启动到c库的start_thread附近时锁在了

pthread_mutex_lock处。

分析C库pthread_create流程:

 

其中,Entry是由于被作为函数传参传递导致的压栈,所以不做考虑。其余的栈的值,都能与C库实现对应上。

继续检查start_thread的反汇编,并重点分析0x121017c7c附近的指令,因其是栈里的最后一条有效PC值(请对照C库start_thread)

 

121017c48: 24050018  li a1,24

121017c4c: 24021494  li v0,5268      

执行5268 (set_robust_list)系统调用(系统调用号见内核unistd.h,后同)

121017c50: 0000000c  syscall

121017c54: dfa60150  ld a2,336(sp)

121017c58: 8cc203d4  lw v0,980(a2)

121017c5c: 30420004  andi v0,v0,0x4

跳转去执行5014(rt_sigprocmask)系统调用

121017c60: 14400089  bnez v0,121017e88 <start_thread+0x290>   

121017c64: df99ad48  ld t9,-21176(gp)

  unwind_buf.priv.data.prev = NULL;

  unwind_buf.priv.data.cleanup = NULL;

121017c68: ffa00130  sd zero,304(sp)

121017c6c: ffa00138  sd zero,312(sp)

121017c70: df990458  ld t9,1112(gp)

121017c74: 0320f809  jalr t9

121017c78: 67a40080  daddiu a0,sp,128

v0是上一步setjmp函数的返回值,即not_first_call的值

如果not_first_call不为0,则去执行121017cb0分支,也就是直接跳出if判断。

if (__builtin_expect (! not_first_call, 1))

121017c7c: 1440000c  bnez v0,121017cb0 <start_thread+0xb8> 

121017c80: dfa20150  ld v0,336(sp)

121017c84: dfa40150  ld a0,336(sp)

121017c88: 904303d3  lbu v1,979(v0)

121017c8c: 67a20080  daddiu v0,sp,128

此处跳转至lll_lock(pd->lock)所在的if分支0x121017ecc

 if (__builtin_expect (pd->stopped_start, 0)) 

121017c90: 1460008e  bnez v1,121017ecc <start_thread+0x2d4>

121017c94: fc8200c0  sd v0,192(a0)

121017c98: dfa20150  ld v0,336(sp)

121017c9c: dc590400  ld t9,1024(v0)

这里调用具体的线程回调,即线程总入口,这里没走到

THREAD_SETMEM (pd, result, pd->start_routine (pd->arg));

121017ca0: 0320f809  jalr t9  

 

 

根据用户态原始栈的分析,有较大嫌疑的地方是start_thread里的lll_lock(pd->lock)导致的死循环。检查lll_lock的底层实现:

 

void

__lll_lock_wait (int *futex)

{

  do

    {

      int oldval = atomic_compare_and_exchange_val_acq (futex, 2, 1);

      if (oldval != 0)

         lll_futex_wait (futex, 2);

    }

  while (atomic_compare_and_exchange_bool_acq (futex, 2, 0) != 0);

}

 

表现是用户态不停的通过lll_futex_wait进内核态。

最先怀疑是发生了乒乓pthread_mutex_lock。

即有两个线程A和B。B获取到lock,A尝试获取lock时发现值为1,因此陷入内核态futex_wait尝试将自己挂起,然而A进到内核后却发现锁已经被B释放,因此直接退出到用户态再次尝试加锁,如果B正好此时又把锁获取到,那么A将再次陷入内核态。如此反复造成这种现象。因为受害者A线程,一直是R状态,并且被动抢占计数在增加,所以推测出问题时,futex_wait不会将自己挂起,而是直接返回,即futex_wait可能从如下出口跑掉。

 

futex_wait:

ret = get_futex_key(uaddr, fshared, &q.key);

if (unlikely(ret != 0))

       goto out_release_sem;

ret = get_futex_value_locked(&uval, uaddr);

if (uval != val)

goto out_unlock_release_sem;

 

 

 

进一步分析get_futex_key的实现,检查里面可能出错的分支,里面有一句比较可疑:

 

if (unlikely((vma->vm_flags & (VM_IO|VM_READ)) != VM_READ))

              return (vma->vm_flags & VM_IO) ? -EPERM : -EACCES;

 

 

 


即是说,如果futex尝试加锁的用户态地址,所在的vma区,具有VM_IO标志的话,则直接返回权限不够错误。再回忆起此锁的地址,确实是特殊分配而来。(发生死锁的lll_lock(pd->lock),其中pd线程描述符是在线程栈空间的头部分配)

检查分配流程:

 确实会对vma区间加上VM_IO属性。

vma->vm_flags |= VM_IO|VM_READ|VM_WRITE|VM_EXEC|VM_MAYREAD|VM_MAYWRITE;

 

 


进一步添加调试代码发现,系统确实是从get_futex_key处返回了无权限错误,导致futex_wait直接返回。其实这也是正常的,用户态不允许对IO空间进行加解锁处理。

 

因此故障复现的可能场景是:

1)父线程A,在pthread_create时,获取到父子线程同步锁 pd->lock(位于巨页栈),往下执行到准备为子线程设置亲和力时,在内核态被其子线程B抢占;

2)子线程B运行至start_thread --> lll_lock (pd->lock); 尝试获取巨页栈里的lock时,发现已经被父进程加锁,则B陷入内核态futex_wait,尝试将自己挂起。然后按照之前的分析,futex如果处于设置了VM_IO属性的vma区间时,是不会做任何处理而直接从内核态返回-EPERM的,因此B返回到用户态后,发现lock的值仍然为1(因为父线程得不到调度,不释放锁),因此再次进入内核态,也就形成了死循环。

3.2 解决方法及验证

去掉VM_IO属性后进行测试,未再发生故障。

1)练习阅读反汇编的能力对排查问题有很大帮助;

2)平时排查故障时可有意培养走查代码的能力。另外在排查故障时最好能摸清这段代码的实现机制,不是为了故障而排查。如果在跟踪的同时也把相关知识一起掌握,对以后排查相似问题有帮助。

3)其实以后可以不用打印用户态原始栈,可以直接在时钟中断里回溯,这样可以减少分析量。(见mips回溯原理)

1.       <glibc 2.5>  createthread.c  pthread_create.c  lowlevellock.c  clone.S

2.       linux kernel 2.6.21.7 futex.c

 

【上篇】
【下篇】

抱歉!评论已关闭.