操作系统: 12 2012存档

生产上报来了内核bug：mysql在做reset master时内核整个panic了。

DBA同学非常热心的帮忙找到了重新步骤：就是一个地雷一样的文件，只要open它，再fdatasync，kernel就panic。

从panic的代码位置看，就是 jbd2_journal_commit_transaction() 里的

J_ASSERT(journal->j_running_transaction != NULL);

判断失败触发panic

但是，为什么jbd2在没有running_transaction的时候也会提交事务？那就只能把所有唤醒kjournald2内核线程（里面调用了jbd2_journal_commit_transaction）的地方——即wake_up(&journal->j_wait_commit)处都加上trace，由于重现步骤是现成的，很快就定位到了原因：open一个文件再直接fdatasync的时候，会调用ext4_sync_file ，里面调用jbd2_log_start_commit开始提交jbd2的日志，jbd2_log_start_commit里会加锁然后调用__jbd2_log_start_commit，代码如下:

int __jbd2_log_start_commit(journal_t *journal, tid_t target)                      

{       

        /* 

         * Are we already doing a recent enough commit?                            

         */

        if (!tid_geq(journal->j_commit_request, target)) {

                /*

                 * We want a new commit: OK, mark the request and wakup the        

                 * commit thread.  We do _not_ do the commit ourselves.            

                 */

                journal->j_commit_request = target;

                jbd_debug(1, "JBD: requesting commit %d/%d\n",                     

                          journal->j_commit_request,

                          journal->j_commit_sequence);

                wake_up(&journal->j_wait_commit);

                return 1;

        }       

        return 0;

}                                                                   

从trace的结果看，journal->j_commit_request的值为2177452108，而target的值为0,看上去j_commit_request显然比target小，应该不会走到if判断里面去，但是实际上是走了的，因为tid_geq的实现是：

static inline int tid_geq(tid_t x, tid_t y)

{

        int difference = (x - y);

        return (difference >= 0);

}               

unsigned int型2177452108减去0然后转为int型，猜猜结果是多少？等于 -2117515188 ！看上去好像tid_geq的实现又罗嗦又奇怪，于是翻了一下注释，才发现，jbd2给每个transaction一个tid，这个tid是不断增长的，而它又是个unsigned int型，所以容易溢出，于是弄出来这么一个tid_geq，把0看成是比2177452108更“晚”的tid，当commit_request为2177452108而target为0时，意思是：编号2177452108的tid已经提交了，0比2177452108更“晚”，所以有必要把0号transaction给commit一下，于是唤醒kjournald2（那句wake_up）。而这一唤醒，就发现没有running_transaction，于是悲剧了。

从trace看，大部分传入__jbd2_log_start_commit的target值都不是0，看来这个0来得蹊跷，翻了一下upstream的代码，找到了Ted在去年3月份提的一个patch：

commit 688f869ce3bdc892daa993534dc6df18c95df931

Date:   Wed Mar 16 17:16:31 2011 -0400

    ext4: Initialize fsync transaction ids in ext4_new_inode()

    When allocating a new inode, we need to make sure i_sync_tid and

    i_datasync_tid are initialized.  Otherwise, one or both of these two

    values could be left initialized to zero, which could potentially

    result in BUG_ON in jbd2_journal_commit_transaction.

    (This could happen by having journal->commit_request getting set to

    zero, which could wake up the kjournald process even though there is

    no running transaction, which then causes a BUG_ON via the

    J_ASSERT(j_ruinning_transaction != NULL) statement.

diff --git a/fs/ext4/ialloc.c b/fs/ext4/ialloc.c

index 2fd3b0e..a679a48 100644

--- a/fs/ext4/ialloc.c

+++ b/fs/ext4/ialloc.c

@@ -1054,6 +1054,11 @@ got:

                }

        }

+       if (ext4_handle_valid(handle)) {

+               ei->i_sync_tid = handle->h_transaction->t_tid;

+               ei->i_datasync_tid = handle->h_transaction->t_tid;

+       }

+

        err = ext4_mark_inode_dirty(handle, inode);

        if (err) {

                ext4_std_error(sb, err);

啊哈，就是它了，由于i_sync_tid和i_datasync_tid都没有正确赋值，所以带上了默认的0值，一路传给ext4_sync_file，而后面的__jbd2_log_start_commit又误认为0是一个要提交的新事务（其实此时还没有把当前事务挂到running_transaction上去),所以错误了。打上这个patch，再走重现步骤kernel也不panic了。

既然这么容易重现为什么其它机器上没有遇到？原因就是这个commit_request必须是一个很大的值，大到转为int型时会变为负数。我试了一下在ext4上不停的创建空文件并fdatasync之，10分钟左右commit_request才变为一百万，如果要让它到二十亿，至少还需要十四天，而线上的io压力毕竟没有人工压力测试那么大，所以几个月后commit_request才到二十亿，才触发了这个bug。

redhat最新的2.6.32-220内核是有这个问题的，大家多小心。

感谢@元云和@希羽两位同学帮忙提供了重现步骤，内核修bug，最难的就是重现，两位却直接把步骤提供出来了，真是太体贴太客气了！

======

本来想用ksplice来不重启升级内核，这样DBA就可以不重启机器修复这个bug，但是研究了一下ksplice，发现它要求加gcc参数 -ffunction-sections -fdata-sections 来编译内核，而这两个参数又和 -pg 参数冲突，而我们的kernel trace需要用到 -pg ，所以....目前无解，还没有办法用ksplice来帮助我们在线升级内核。

把flashcache改为request-based后，虽然IO数量可以按比例控制了，但是作为”珍稀“资源的cache（通常是昂贵的固态硬盘或更昂贵的fusionio卡），也需要按例分配不同进程以不同的cache空间。近一个月我一直在忙着加这个功能。

新代码写完了，压力测试二十多个小时，出现了一个死锁：

<4>[11957.888102]  [<ffffffff814afa70>] ? nmi+0x20/0x30

<4>[11957.897016]  [<ffffffff814af1cf>] ? _spin_lock_irqsave+0x2f/0x40

<4>[11957.906089]  <<EOE>>  [<ffffffffa0443faf>] ? flashcache_clean_set+0x9f/0x600 [flashcache]

<4>[11957.915610]  [<ffffffffa0442f1c>] ? dm_io_async_bvec+0xbc/0xf0 [flashcache]

<4>[11957.925377]  [<ffffffffa04429c0>] ? flashcache_io_callback+0x0/0x4a0 [flashcache]

<4>[11957.935318]  [<ffffffffa0444cfe>] ? flashcache_read_miss+0x9e/0x150 [flashcache]

<4>[11957.945378]  [<ffffffffa0444ee8>] ? flashcache_read+0x138/0x330 [flashcache]

<4>[11957.955511]  [<ffffffffa0445245>] ? flashcache_mk_rq+0x165/0x1d0 [flashcache]

<4>[11957.965677]  [<ffffffffa00034bd>] ? dm_request+0x5d/0x210 [dm_mod]

<4>[11957.975911]  [<ffffffff812400c1>] ? generic_make_request+0x261/0x530

应该是有进程拿到了request_queue的锁 queue_lock 却再没有释放。

由于出现了“flashcache”的字样，有很大嫌疑是我新加的代码有问题，但是不管怎样，二十多个小时的重现步骤太慢了，得找到一个快点的，于是花了几天尝试不同的压测脚本（一边尝试，一边把我的cubieboard刷成了android，我的天，android比linaro好用多了，而且是刷在cubieboard自带的NAND里，可以不用SD卡，刷机所需image见这里），终于把重现步骤缩短为2个小时左右，接下来把我加的代码全回退，依然有死锁——看来是redhat-2.6.32内核的问题了。

我在内核报死锁的地方watchdog_overflow_callback()函数里调用panic()之前加了一句show_state()，即把死锁时所有进程的stack信息统统输出到dmesg里去(再依靠netoops把消息传到另外一台机器上，因为出现死锁的本机已经登不上去了）。

跑了不到两个小时，死锁出现了，我在netoops吐出来的一堆stack信息里一个个找，看谁像是那个拿到锁不还的人，发现一个可疑的：cfq_get_cfqg()里调用blk_init_rl()函数。blk_init_rl函数里面要做一个内存分配，但是传给kmalloc_node的gfp_mask却是GFP_KERNEL，带上GFP_KERNEL后在分配不到内存时进程会去睡眠直到别的进程释放了一些可用内存，blk_init_rl()已经拿到了queue_lock，现在却一睡不醒（系统内存紧张，迟迟没有可用内存），当然别的进程来取queue_lock就等疯了。

看来不是我加的代码造成的，也与flashcache没有关系，是block层的问题。

这种情况一般有两种修复办法：一是在分配内存之前把queue_lock释放掉，分配后再重新拿锁;或者，把分配内存的gfp_mask设为GFP_ATOMIC，就是没内存就直接返回NULL，不睡。

不过我看了一下upstream代码，这个问题已经修复了。参见Tejun Heo的两个patch，1，2，第二个patch的头几个改动才是把GFP_KERNEL改成GFP_ATOMIC。

没想到netoops加show_state()调试死锁这么方便，当然，难的是找到快速重现bug的办法。

PPT地址 http://wenku.baidu.com/view/3a5db5b5960590c69ec3767d.html