[原写于2012年12月]

生产上报来了内核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来帮助我们在线升级内核。