smp_call_function_many死锁问题分析
前言
这是我遇到的一个离奇的内核死锁问题,现象倒是不复杂,是一个常见的smp_call_function_many的软死锁。但在分析问题的过程中却越挖越深,解决一个问题后又冒出一个问题,顺藤摸瓜的揪出了最后的问题根源。过程中充分利用了内核分析工具,也学习到了不少新知识。下面就将问题的分析和定位过程跟大家分享一下,共同进步。因为过程有点长,准备以一个系列文章的形式来描述,请各位看官耐心。
1.第一现场
先交待一下问题的背景和环境。我的设备环境是使用Intel CPU的设备,属于服务器架构。操作系统是CentOS7,自己裁剪的内核,内核版本是4.9.25。运行过程中高概率的复现一个死锁问题,问题复现时系统日志中有出错信息,出现这个日志后概率出现系统没有反应(无法输入也没有输出,网络也不通)。
通常这类问题的分析都要从分析这个堆栈信息开始,首先要看的是错误类型和错误提示。可以确定这是一个soft lockup错误,也就是软死锁。出问题的进程是"libvirtd"。
NMI watchdog: BUG: soft lockup - CPU#2 stuck for 134s! [libvirtd:9410]
再进一步的可以看出现问题的函数:“smp_call_function_many
”,这个函数在内核的"kernel\smp.c
"文件中。
RIP: 0010:[<ffffffff810ccccf>] [<ffffffff810ccccf>] smp_call_function_many+0x1ef/0x250
第三步可以从堆栈信息中看到错误出现时的函数调用过程。在Call Trace中可以看到直接调用出问题的函数是:“on_each_cpu
”。
至此现场信息已经看完了,随之而来的是一堆问题。
- 什么是“
soft lockup
”? - 这个“
smp_call_function_many
”函数是做什么的,为什么会在这个函数里lockup? - 这个lockup是否和这个Call Trace中显示的调用路径相关?
其中这第三个问题先按下不表,从前两个问题开始分析。
2.问题分析
2.1 问题背景知识
soft lockup
此章节参考Linux内核为什么会发生soft lockup?
先解释一下soft lockup,指的是发生的CPU上在一段时间内(默认是20秒)中没有发生调度切换。从上面的出错信息来看这个进程已经有134秒没有发生调度切换了。这里有可能是发生了死循环,或者是一种忙等,导致这个进程一直占据这个CPU(CPU#2)。
smp_call_function函数作用
这一类函数是内核中用于跨CPU的操作的函数,常用于的同步关键信息的操作。在SMP架构中不同的CPU核心之间通过这类函数对指定的CPU或多个CPU发IPI消息,目标CPU收到该消息进入中断处理函数,进而调用参数上的func函数指针执行指定操作。
上面信息中的smp_call_function_many
函数就是,从CPU#2发送一个IPI消息给其他所有的其他CPU,让大家统一进行一个操作。
2.2 查找出错的代码行
要搞清楚为什么会在smp_call_function_many
函数发生soft lockup
,我们还是要回到代码来分析到底发生了什么?你可以在内核的"kernel\smp.c
"文件中找到函数的代码。我这里并不准备深入分析内核的IPI实现机制,只是通过对代码分析来定位问题。如果对IPI机制的实现和运作有兴趣可以参考后面的参考阅读。
void smp_call_function_many(const struct cpumask *mask,
smp_call_func_t func, void *info, bool wait)
{
struct call_function_data *cfd;
int cpu, next_cpu, this_cpu = smp_processor_id();
/*
* Can deadlock when called with interrupts disabled.
* We allow cpu's that are not yet online though, as no one else can
* send smp call function interrupt to this cpu and as such deadlocks
* can't happen.
*/
WARN_ON_ONCE(cpu_online(this_cpu) && irqs_disabled()
&& !oops_in_progress && !early_boot_irqs_disabled);
/* Try to fastpath. So, what's a CPU they want? Ignoring this one. */
cpu = cpumask_first_and(mask, cpu_online_mask);
if (cpu == this_cpu)
cpu = cpumask_next_and(cpu, mask, cpu_online_mask);
/* No online cpus? We're done. */
if (cpu >= nr_cpu_ids)
return;
/* Do we have another CPU which isn't us? */
next_cpu = cpumask_next_and(cpu, mask, cpu_online_mask);
if (next_cpu == this_cpu)
next_cpu = cpumask_next_and(next_cpu, mask, cpu_online_mask);
/* Fastpath: do that cpu by itself. */
if (next_cpu >= nr_cpu_ids) {
smp_call_function_single(cpu, func, info, wait);
return;
}
cfd = this_cpu_ptr(&cfd_data);
cpumask_and(cfd->cpumask, mask, cpu_online_mask);
cpumask_clear_cpu(this_cpu, cfd->cpumask);
/* Some callers race with other cpus changing the passed mask */
if (unlikely(!cpumask_weight(cfd->cpumask)))
return;
for_each_cpu(cpu, cfd->cpumask) {
struct call_single_data *csd = per_cpu_ptr(cfd->csd, cpu);
csd_lock(csd);
if (wait)
csd->flags |= CSD_FLAG_SYNCHRONOUS;
csd->func = func;
csd->info = info;
llist_add(&csd->llist, &per_cpu(call_single_queue, cpu));
}
/* Send a message to all CPUs in the map */
arch_send_call_function_ipi_mask(cfd->cpumask);
if (wait) {
for_each_cpu(cpu, cfd->cpumask) {
struct call_single_data *csd;
csd = per_cpu_ptr(cfd->csd, cpu);
csd_lock_wait(csd);
}
}
}
这里我们首先再次利用第一现场的信息来定位出现问题的代码行。
这里可以看出在smp_call_function_many函数的偏移量0x1ef
(十进制:495
)处出现了问题。通过gdb内核debuginfo可以看到这个函数偏移量对应的代码行。
# gdb ./vmlinux
(gdb) l* smp_call_function_many+495
0xffffffff810ccccf is in smp_call_function_many (./include/linux/compiler.h:243).
238 ./include/linux/compiler.h: No such file or directory.
gdb给出的是一个头文件中compiler.h:243
的宏定义:
static __always_inline
void __read_once_size(const volatile void *p, void *res, int size)
{
__READ_ONCE_SIZE;
}
gdb显示是__READ_ONCE_SIZE
这一行。这个是被内联进函数中的一段代码,并不能直接看出在函数smp_call_function_many中的位置。我们需要在出错位置的周边来看看是否能直接找到对应的代码行。使用gdb反汇编函数,得到出问题偏移量周边的语句偏移量:
(gdb) disass smp_call_function_many
Dump of assembler code for function smp_call_function_many:
0xffffffff810ccae0 <+0>: callq 0xffffffff81844bd0 <__fentry__>
0xffffffff810ccae5 <+5>: push %rbp
0xffffffff810ccae6 <+6>: mov %rsp,%rbp
0xffffffff810ccae9 <+9>: push %r15
0xffffffff810ccaeb <+11>: mov %rdx,%r15
...
0xffffffff810cccc9 <+489>: test $0x1,%al
0xffffffff810ccccb <+491>: je 0xffffffff810cccd6 <smp_call_function_many+502>
0xffffffff810ccccd <+493>: pause
0xffffffff810ccccf <+495>: mov 0x18(%rcx),%eax
0xffffffff810cccd2 <+498>: test $0x1,%al
0xffffffff810cccd4 <+500>: jne 0xffffffff810ccccd <smp_call_function_many+493>
...
0xffffffff810ccd19 <+569>: mov %r12,%rsi
0xffffffff810ccd1c <+572>: mov %eax,%edi
0xffffffff810ccd1e <+574>: callq 0xffffffff8145a440 <cpumask_next_and>
0xffffffff810ccd23 <+579>: jmpq 0xffffffff810ccbaf <smp_call_function_many+207>
End of assembler dump.
(gdb)
再尝试获取函数在偏移量为493
和491
的代码行:
(gdb) l* smp_call_function_many+493
0xffffffff810ccccd is in smp_call_function_many (./arch/x86/include/asm/processor.h:584).
579 ./arch/x86/include/asm/processor.h: No such file or directory.
(gdb) l* smp_call_function_many+491
0xffffffff810ccccb is in smp_call_function_many (kernel/smp.c:96).
91 kernel/smp.c: No such file or directory.
可以看到smp_call_function_many+491
的这个偏移量对应的是kernel/smp.c:96
的代码行。这个就接近很多了,同样这也是一个内联函数:
static __always_inline void csd_lock_wait(struct call_single_data *csd)
{
smp_cond_load_acquire(&csd->flags, !(VAL & CSD_FLAG_LOCK));
}
在smp_call_function_many
函数代码中最后调用了csd_lock_wait
函数。
同时,还可以看到csd_lock_wait函数调用的smp_cond_load_acquire
宏定义中包含了READ_ONCE
,READ_ONCE
这个宏最终会调用__read_once_size
宏,就是第一现场中指示的偏移量smp_call_function_many+495
引用的宏。
#define smp_cond_load_acquire(ptr, cond_expr) ({ \
typeof(ptr) __PTR = (ptr); \
typeof(*ptr) VAL; \
for (;;) { \
VAL = READ_ONCE(*__PTR); \
if (cond_expr) \
break; \
cpu_relax(); \
} \
smp_acquire__after_ctrl_dep(); \
VAL; \
})
这样基本可以确定出错时的代码行:smp_call_function_many
内联的csd_lock_wait
函数,这个函数再内联smp_cond_load_acquire
再内联调用__read_once_size
的这一句。
2.3 smp_call_function_many死循环
通过上面的分析,我们将注意力集中到smp_call_function_many
函数的这几行代码:
这段代码告诉我们smp_call_function_many函数在这里遍历每个收到IPI消息CPU,并等待他们做出响应。再看smp_cond_load_acquire
宏定义中,有一个for( ; ; )的无限循环一直读取变量。由此可以基本判断问题的现象就是由这个无限循环产生的。也就是等待的某个CPU响应一直没有回应。
3 初步结论
结合上面的背景知识和这段代码的分析,我们可以得到一个初步的结论:该问题是由CPU#2发起了一个smp_call_function请求,向其他的CPU发送IPI信息,接收到IPI消息的CPU根据函数中的func函数指针进行处理,处理完成的CPU将设置对应的csd结构以告知完成该请求;发起方的CPU#2会遍历所有的CPU的csd结构以确认请求都被执行;如果其中一个CPU没有完成,则循环等待其完成;如果某个CPU长时间的没有完成,就会导致发起者CPU#2的忙等操作出现soft lockup。
问题分析到这里并没有实质的进展,只是产生了更多的新问题。看到的出错信息和现象只是表象,或者说CPU#2出现的soft lockup也是受害者。为了进一步的分析该问题有两个方向可以继续努力:1)找到那个一直没有处理IPI的CPU,看看能否得知是什么原因引起;2)分析出错信息中的Call Trace看看具体是个什么样的任务需要大家一起完成,也就是IPI发送的信息是为了做什么。
显然第一个方向更容易一点,在下一篇中将从出错信息中分析如何找到是哪个CPU没有处理IPI信息,并给出一个定位这类问题的有效方法,敬请关注下一篇。