Linux内核--修复ext4日志（jbd2）bug

生产上报来了内核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
Author: Theodore Ts'o 
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.
    Signed-off-by: "Theodore Ts'o" 
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来帮助我们在线升级内核。

原文作者: 斯巴达第二季

原文地址：http://wp.me/p3N0Wv-U（版权归原文作者所有，侵权留言联系删除）