MyException - 我的异常网
当前位置:我的异常网» 研发管理 » 钟表中断导致的内核模块死锁

钟表中断导致的内核模块死锁

www.myexceptions.net  网友分享于:2013-04-10  浏览:88次
时钟中断导致的内核模块死锁
   这篇文章是对这几天找的一个BUG的总结,如果理解上有不对的地方,或者有更好的建议,希望看到的朋友能够指出。
  问题是这样的:内核模块中有一个哈希表来维护模块中管理的连接,哈希表是用一个读写锁数组来互斥的,每个锁管理一段哈希表槽位。模块中的处理主要有这几个分支:NF_INET_LOCAL_IN和NF_INET_POST_ROUTING两个钩子点的处理函数,一个是定时器处理函数fcluster_timer_process()。死锁出现在两个地方是在定时器处理函数fcluster_timer_process()中获取写锁时一直阻塞,导致占有CPU时间过长,引发softlockup机制的处理,触发panic操作。
   遇到死锁的问题,首先肯定是怀疑自己的代码逻辑中出现了纰漏,所以再次仔细地检查了代码逻辑,发现不会出现没有释放锁的情况。接下来在代码中添加调试信息,在获取锁的时候进行统计,并且在可能导致没有释放锁的地方都加了调试信息,但是还是没有发现问题。内核开发中遇到这样的问题,真是很头疼。内核太庞大了,就算你的逻辑没问题,也有可能因为对内核机制的某些情况不了解导致操作的时机不对。在用户层应用程序中,有gdb可以查看栈信息,单步调试可以看到执行的逻辑,在内核中有很多东西都要靠源码来分析。现在我把最先想到,也是大部分人都会做的两步操作都做了,而且重复了多次,但是依然找不到问题原因,这时心中真是很烦,很不知所措,不知道下一步该怎么做。
  问题还在,也不能什么也不做,一次次地修改添加调试信息的位置,一次次地打印一些参数和变量的值,但是依然没有进展。在测试的过程中我发现了一个系统参数softlock_panic,可以在内核线程占有CPU时间过长的情况下执行panic操作。因为我已经安装了kdump,所以在内核执行panic操作后,会得到一份core文件,这个core文件太宝贵了!

  通过core文件可以看到内核崩溃时的堆栈信息,对进一步查找bug很有帮助。可是这时我犯了一个错误,还是在想通过打印日志的方式来定位出BUG原因。跟随着这个错误的想法,依然没有任何头绪。最终我开始把注意力放在堆栈信息上,因为我发现每次阻塞的进程都是应用层的进程(内核模块和应用层有交互),并且调用的流程都是从sys_close()系统调用开始的。而调用堆栈的后半部分,则是处理时钟中断的部分,处理时候中断的时候,还调用到了我的定时器处理函数。堆栈信息如下所示:

Kernel panic - not syncing: softlockup: hung tasks
Pid: 2826, comm: fastcache Not tainted 2.6.32-279.el6.x86_64 #1
Call Trace:
 <IRQ>  [<ffffffff814fd11a>] ? panic+0xa0/0x168
[<ffffffff810dadb0>] ? watchdog_timer_fn+0x0/0x1d0
[<ffffffff810daf6d>] ? watchdog_timer_fn+0x1bd/0x1d0
[<ffffffff8109684e>] ? __run_hrtimer+0x8e/0x1a0
[<ffffffff81012bd9>] ? read_tsc+0x9/0x20
[<ffffffff81096bf6>] ? hrtimer_interrupt+0xe6/0x250
[<ffffffffa0259780>] ? fcluster_timer_process+0x0/0x1b0 [fcluster]
[<ffffffff81505bdb>] ? smp_apic_timer_interrupt+0x6b/0x9b
[<ffffffff8100bc13>] ? apic_timer_interrupt+0x13/0x20
[<ffffffff8127e4ef>] ? __write_lock_failed+0xf/0x20
[<ffffffff81500147>] ? _write_lock+0x17/0x20
[<ffffffffa02597d5>] ? fcluster_timer_process+0x55/0x1b0 [fcluster]
[<ffffffff8107e897>] ? run_timer_softirq+0x197/0x340
[<ffffffff810a21c0>] ? tick_sched_timer+0x0/0xc0
[<ffffffff8102b40d>] ? lapic_next_event+0x1d/0x30
[<ffffffff81073ec1>] ? __do_softirq+0xc1/0x1e0
[<ffffffff81096c50>] ? hrtimer_interrupt+0x140/0x250
[<ffffffff8100c24c>] ? call_softirq+0x1c/0x30
[<ffffffff8100de85>] ? do_softirq+0x65/0xa0
[<ffffffff81073ca5>] ? irq_exit+0x85/0x90
[<ffffffff81505be0>] ? smp_apic_timer_interrupt+0x70/0x9b
[<ffffffff8100bc13>] ? apic_timer_interrupt+0x13/0x20
 <EOI>  [<ffffffff814fffcd>] ? _read_lock+0xd/0x20
[<ffffffffa0258ca1>] ? fcluster_conn_out_get+0x51/0xe0 [fcluster]
[<ffffffffa02577cd>] ? fcluster_out+0x9d/0x130 [fcluster]
[<ffffffff815002fb>] ? _spin_unlock_bh+0x1b/0x20
[<ffffffff8142b45e>] ? release_sock+0xce/0xe0
[<ffffffff814665e9>] ? nf_iterate+0x69/0xb0
[<ffffffff81476fb0>] ? ip_finish_output+0x0/0x310
[<ffffffff814667a4>] ? nf_hook_slow+0x74/0x110
[<ffffffff81476fb0>] ? ip_finish_output+0x0/0x310
[<ffffffff81477364>] ? ip_output+0xa4/0xc0
[<ffffffff81476675>] ? ip_local_out+0x25/0x30
[<ffffffff81476b50>] ? ip_queue_xmit+0x190/0x420
[<ffffffff810724c7>] ? current_fs_time+0x27/0x30
[<ffffffff814281c3>] ? sock_recvmsg+0x133/0x160
[<ffffffff81194ea2>] ? file_update_time+0x62/0x170
[<ffffffff8148b89e>] ? tcp_transmit_skb+0x3fe/0x7b0
[<ffffffff8148dc5b>] ? tcp_write_xmit+0x1fb/0xa20
[<ffffffff811637fb>] ? __kmalloc_node+0x7b/0x100
[<ffffffff8142480a>] ? sock_poll+0x1a/0x20
[<ffffffff8148e610>] ? __tcp_push_pending_frames+0x30/0xe0
[<ffffffff8148e732>] ? tcp_send_fin+0x72/0x1d0
[<ffffffff8147fc26>] ? tcp_close+0x356/0x460
[<ffffffff814a2d47>] ? inet_release+0x67/0x90
[<ffffffff81427169>] ? sock_release+0x29/0x90
[<ffffffff814271e7>] ? sock_close+0x17/0x30
[<ffffffff8117c935>] ? __fput+0xf5/0x210
[<ffffffff8117ca75>] ? fput+0x25/0x30
[<ffffffff8117849d>] ? filp_close+0x5d/0x90
[<ffffffff81178575>] ? sys_close+0xa5/0x100
[<ffffffff8100b0f2>] ? system_call_fastpath+0x16/0x1b
  这个堆栈信息要从下往上看,也就是说引发这一系列操作是从system_call_fastpath()开始的,时钟中断的处理时从apic_timer_interrupt()函数开始的。每行后面以[fcluster]结束的行对应的函数是我的内核模块中的函数。通过这个堆栈信息可以看到,在_read_lock()函数(这个函数在fcluster_conn_out_get()中间接调用到)执行时发生了时钟中断,进而开始进行软中断的处理,调用到了定时器处理函数fcluster_timer_process()。在fcluster_timer_process()中会有获取写锁的操作,这个操作的时间过长引发了softlockup机制的处理。CentOS6.3的279内核中处理的函数是watchdog_timer_fn(),在这个函数中最终引发了panic操作。
  为什么在定时器处理函数中获取写锁失败呢?可能的原因是在fcluster_conn_out_get()中获取读锁后,发生了时钟中断,进而会调用到定时器处理函数fcluster_timer_process()。如果在这两个函数中获取的都是同一个锁,就会发生死锁。因为在调用read_lock()获取锁的时候,会禁止内核抢占,所以导致获取锁后被切换或者中断的话,只有可能是中断了。下一个问题就是要确定从system_call_fastpath()到钩子处理函数fcluster_conn_out_get()的过程中是否禁止了中断,也就是说检查一下fcluster_conn_out_get()执行时所处的上下文环境中是否包含禁止本地中断。按照上面的堆栈信息,没有发现禁止中断的地方,而且当前所处的进程是用户进程,也不肯能会禁止中断。所以我就在fcluster_conn_out_get()中获取读锁的时候,将read_lock()替换为read_lock_irqsave(),在获取锁的时候,也禁止本地中断,这时时钟中断也会被禁止。由于这个锁保护的区域中操作会很快会完成,不会长时间禁止中断,所以不会有问题。可能会有人担心,这里禁止中断会导致系统时间滞后,这个担心是多余的。时钟中断是可以被屏蔽的, 但是内核在每一次时钟中断服务时,都会做时钟修正。在X86下根据X86的TSC寄存器来对时间进行更正, 这样就可以保证被时钟中断虽然被中断了, 但是仍然是可以在后来被补上的(同事找到的,这里感谢一下)。只要你保证你禁止中断的时间很短,是不会有问题的。
  我在前面提到过在NF_INET_LOCAL_IN和NF_INET_POST_ROUTING两个钩子处都有处理函数,但是在所有拿到的core文件中,都没有发现是在NF_INET_LOCAL_IN处的处理函数过程中发生问题,为什么在这个处理函数中出现上面讲的死锁呢?这时因为在NF_INET_LOCAL_IN处的处理是在禁用中断的情况下执行的,跟用户态进程完全没有关系,也没有交互,所以不会被中断。

文章评论

软件开发程序错误异常ExceptionCopyright © 2009-2015 MyException 版权所有