另一方面,也说明内核开发中,坑很多,这只是一个小坑,要写内核代码,还需多修炼。
一、问题
环境中出现了softlockup,触发了panic,堆栈如下:
[16698.440604] BUG: soft lockup - CPU#0 stuck for 22s! [ps:6851]
[16698.442430] CPU: 0 PID: 6851 Comm: ps Tainted: GF O-------------- 3.10.0-123.el7.x86_64 #1
[16698.442436] task: ffff882027ed8000 ti: ffff881fab9fa000 task.ti: ffff881fab9fa000
[16698.442438] RIP: 0010:[<ffffffff815f7087>] [<ffffffff815f7087>] _raw_spin_lock+0x37/0x50
[16698.442447] RSP: 0018:ffff88103fc03de0 EFLAGS: 00000206
[16698.442449] RAX: 00000000000075bb RBX: ffff88103fc03e10 RCX: 0000000000006e9a
[16698.442451] RDX: 0000000000006e9c RSI: 0000000000006e9c RDI: ffff881e394c79c0
[16698.442453] RBP: ffff88103fc03de0 R08: 1000000000000000 R09: 0000000000000000
[16698.442455] R10: 8840000000000000 R11: 0001f9b93d719108 R12: ffff88103fc03d58
[16698.442457] R13: ffffffff81600e5d R14: ffff88103fc03de0 R15: ffff881e394c71c0
[16698.442460] FS: 00007f09afb34740(0000) GS:ffff88103fc00000(0000) knlGS:0000000000000000
[16698.442462] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[16698.442464] CR2: 00007fff5a1aaf98 CR3: 00000009f220b000 CR4: 00000000000427f0
[16698.442466] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[16698.442469] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[16698.442470] Stack:
[16698.442472] ffff88103fc03e20 ffffffff813dceae ffff88101a114c00 ffffffff81cb14c0
[16698.442479] ffffffff81e233a0 0000000000000100 ffffffff813dcde0 ffffffff81e233f0
[16698.442484] ffff88103fc03e58 ffffffff8106d9d6 ffffffff81cb14c0 00000000000000ff
[16698.442489] Call Trace:
[16698.442492] <IRQ>
[16698.442500] [<ffffffff813dceae>] Timeout_callback+0xce/0x220
[16698.442504] [<ffffffff813dcde0>] ? init_dom_starttime+0x250/0x250
[16698.442510] [<ffffffff8106d9d6>] call_timer_fn+0x36/0x110
[16698.442514] [<ffffffff813dcde0>] ? init_dom_starttime+0x250/0x250
[16698.442519] [<ffffffff8106fabf>] run_timer_softirq+0x21f/0x320
[16698.442525] [<ffffffff81067497>] __do_softirq+0xf7/0x290
[16698.442530] [<ffffffff81601b1c>] call_softirq+0x1c/0x30
[16698.442537] [<ffffffff81014d35>] do_softirq+0x55/0xa0
[16698.442541] [<ffffffff81067abd>] irq_exit+0x25d/0x270
[16698.442545] [<ffffffff816024f5>] smp_apic_timer_interrupt+0x45/0x60
[16698.442550] [<ffffffff81600e5d>] apic_timer_interrupt+0x6d/0x80
[16698.485272] <EOI> [<ffffffff81224847>] ? proc_pid_status+0x2b7/0x6d0
[16698.486741] [<ffffffff81224827>] ? proc_pid_status+0x297/0x6d0
[16698.488205] [<ffffffff8122049d>] proc_single_show+0x4d/0x80
[16698.489621] [<ffffffff811d9ece>] seq_read+0x16e/0x3b0
[16698.491041] [<ffffffff811b5aec>] vfs_read+0x9c/0x170
[16698.492419] [<ffffffff811b6618>] SyS_read+0x58/0xb0
[16698.493764] [<ffffffff816001d9>] system_call_fastpath+0x16/0x1b
二、分析
1、直接原因
从堆栈可以看出,最终是在spinlock上发生了阻塞。流程是位于定时器的软中断处理中。其中Timeout_callback是用户自己编写的定时器handler。
根据其代码分析,是因为在其中使用了task_lock(),而x86环境中task_lock()就是spin_lock()的简单封装:
点击(此处)折叠或打开
-
static inline void task_lock(struct task_struct *p)
-
{
-
spin_lock(&p->alloc_lock);
- }
2、根本原因
再看看内核栈中的内容:
[16698.485272] <EOI> [<ffffffff81224847>] ? proc_pid_status+0x2b7/0x6d0
[16698.486741] [<ffffffff81224827>] ? proc_pid_status+0x297/0x6d0
[16698.488205] [<ffffffff8122049d>] proc_single_show+0x4d/0x80
[16698.489621] [<ffffffff811d9ece>] seq_read+0x16e/0x3b0
[16698.491041] [<ffffffff811b5aec>] vfs_read+0x9c/0x170
[16698.492419] [<ffffffff811b6618>] SyS_read+0x58/0xb0
[16698.493764] [<ffffffff816001d9>] system_call_fastpath+0x16/0x1b
可以看出是在读取/proc接口中的进程相关信息,最终在 proc_pid_status函数中发生了时钟中断,从而进入了上述的定时器软中断流程。而 proc_pid_status函数中有很多使用task_lock的地方:
点击(此处)折叠或打开
-
/usr/src/debug/kernel-3.10.0-123.el7/linux-3.10.0-123.el7.x86_64/include/linux/spinlock.h: 293
-
0xffffffff8122481f <proc_pid_status+655>: mov %r14,%rdi
-
0xffffffff81224822 <proc_pid_status+658>: callq 0xffffffff815f7050 <_raw_spin_lock> //这里就是task_lock锁
-
/usr/src/debug/kernel-3.10.0-123.el7/linux-3.10.0-123.el7.x86_64/fs/proc/array.c: 207
-
0xffffffff81224827 <proc_pid_status+663>: mov 0x758(%r12),%rax
-
0xffffffff8122482f <proc_pid_status+671>: test %rax,%rax
-
0xffffffff81224832 <proc_pid_status+674>: je 0xffffffff81224c28 <proc_pid_status+1688>
-
/usr/src/debug/kernel-3.10.0-123.el7/linux-3.10.0-123.el7.x86_64/fs/proc/array.c: 208
-
0xffffffff81224838 <proc_pid_status+680>: mov 0x8(%rax),%rax
-
/usr/src/debug/kernel-3.10.0-123.el7/linux-3.10.0-123.el7.x86_64/fs/proc/array.c: 209
-
0xffffffff8122483c <proc_pid_status+684>: test %rax,%rax
-
0xffffffff8122483f <proc_pid_status+687>: je 0xffffffff81224c28 <proc_pid_status+1688>
-
0xffffffff81224845 <proc_pid_status+693>: mov (%rax),%edx
- 0xffffffff81224847 <proc_pid_status+695>: mov $0xffffffff818214bb,%rsi //这里是被中断的IP
所以问题就来了,由于在 proc_pid_status中使用了task_lock(),而发生中断后,在中断上下文中再次使用了task_lock()获取同一把锁,从而导致了死锁。
所以,该问题是spin_lock()锁的使用问题,spin_lock(task_lock)由于没有关中断,就不能用在中断上下文中,否则重入可能导致死锁.
三、结论及思考
本问题是个简单的内核编程问题(spin_lock的用法问题):spin_lock(task_lock)不能直接在中断上下文中使用,因为这样的锁没有关中断,他可能被中断打断,然后中断上下文中如果再次获取该锁就导致死锁了,除非能确认该锁不会在其它地方使用。
问题很简单,但却很有警示意义。可能有人认为内核代码随便就能写,模仿模仿就行,但实际上,内核编程水很深、坑很多,稍不留神(对相关用法和原理了解不够)就可能会掉坑里,立马掉进去还好,最怕就是给自己埋雷,不知道哪一天会踩到,到时后果就很严重了,所以,对内核的任何改动或新增代码,都需要千万谨慎,多修炼吧!