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

时钟中断导致的内核模块死锁
   这篇文章是对这几天找的一个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处的处理是在禁用中断的情况下执行的，跟用户态进程完全没有关系，也没有交互，所以不会被中断。