生產上報來了內核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來幫助我們在線升級內核。