rhel6再次发现jbd2的bug

从上次修复jbd2的bug后到现在,已经四个月了,突然昨天DB的机器又出现了panic,用netoops抓到的信息如下:
jbd2 panic
居然又栽在jbd2上了,panic的位置和上次一样是

J_ASSERT(journal->j_running_transaction != NULL);

考虑到是运行很长时间的DB机器才出现这个问题,疑点还是落到tid上,由文卿同学找到了现象最符合的upstream的补丁:

commit deeeaf13b291420fe4a4a52606b9fc9128387340
Author: Theodore Ts'o 
Date:   Sun May 1 18:16:26 2011 -0400

    jbd2: fix fsync() tid wraparound bug
    
    If an application program does not make any changes to the indirect
    blocks or extent tree, i_datasync_tid will not get updated.  If there
    are enough commits (i.e., 2**31) such that tid_geq()'s calculations
    wrap, and there isn't a currently active transaction at the time of
    the fdatasync() call, this can end up triggering a BUG_ON in
    fs/jbd2/commit.c:
    
    	J_ASSERT(journal->j_running_transaction != NULL);
    
    It's pretty rare that this can happen, since it requires the use of
    fdatasync() plus *very* frequent and excessive use of fsync().  But
    with the right workload, it can.
    
    We fix this by replacing the use of tid_geq() with an equality test,
    since there's only one valid transaction id that we is valid for us to
    wait until it is commited: namely, the currently running transaction
    (if it exists).
    
    Signed-off-by: "Theodore Ts'o" 

diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index e0ec3db..8c10004 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -479,9 +479,12 @@ int __jbd2_log_space_left(journal_t *journal)
 int __jbd2_log_start_commit(journal_t *journal, tid_t target)
 {
 	/*
-	 * Are we already doing a recent enough commit?
+	 * The only transaction we can possibly wait upon is the
+	 * currently running transaction (if it exists).  Otherwise,
+	 * the target tid must be an old one.
 	 */
-	if (!tid_geq(journal->j_commit_request, target)) {
+	if (journal->j_running_transaction &&
+	    journal->j_running_transaction->t_tid == target) {
 		/*
 		 * We want a new commit: OK, mark the request and wakeup the
 		 * commit thread.  We do _not_ do the commit ourselves.
@@ -493,7 +496,14 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
 			  journal->j_commit_sequence);
 		wake_up(&journal->j_wait_commit);
 		return 1;
-	}
+	} else if (!tid_geq(journal->j_commit_request, target))
+		/* This should never happen, but if it does, preserve
+		   the evidence before kjournald goes into a loop and
+		   increments j_commit_sequence beyond all recognition. */
+		WARN(1, "jbd: bad log_start_commit: %u %u %u %u\n",
+		     journal->j_commit_request, journal->j_commit_sequence,
+		     target, journal->j_running_transaction ? 
+		     journal->j_running_transaction->t_tid : 0);
 	return 0;
 }

原来,做fdatasync()时,会调用 ext4_sync_file():

fs/ext4/fsync.c
ext4_sync_file()

        commit_tid = datasync ? ei->i_datasync_tid : ei->i_sync_tid;                        
        printk("datasync:%lu, sync:%lu\n", ei->i_datasync_tid, ei->i_sync_tid);             
        if (jbd2_log_start_commit(journal, commit_tid)) {                                
		......

直接把i_datasync_tid赋给target,然后调用__jbd2_log_start_commit(),由于i_datasync_tid只在新创建inode或者ext4_iget()时更新,而数据库在打开某些文件后几乎再不关闭,而且一直是覆盖写,extent树不变,故而i_datasync_tid始终不更新,保持一个很小的值,而j_commit_request却随着jbd2日志的不断提交而不停增长,最后,它俩的差值越来越大,直至差值超过int型上限,tid_geq判断出错。

真是此恨绵绵,上次通过给i_datasync_tid赋正确的初值避免了“0比2177452108更晚”这一逻辑错误,修复了,但现在又是由于j_commit_request和target之间差值太大(大于了2的31次方)再次造成判断错误,所以又触发了BUG_ON。这次明显Ted哥也抓狂了,折腾tid_geq这破逻辑干嘛,直接判断j_running_transaction是不是NULL得了....

重现方法由伯瑜发现:打开一个文件,不停的覆盖写和fdatasync();另外启动一个进程打开另一个文件不停覆盖写和fsync()。重现时间需要三个多月,我们在线下修改了部分内核代码才加速复现的。
上次线上临时修复这个问题是umount ext4文件系统后用专用工具直接将tid置为0,这次其实临时方案更简单:umount后再mount就行了,因为这样会让i_datasync_tid更新为最新的tid,避免了它们之间差值不断变大。当然,文卿同学正在用kprobe的机制写了个hotfix的内核模块,这个才是正解。

DB的运维同学又渡过了一个难眠的夜晚,给大家添麻烦了,实在抱歉!

Ext4 Workshop 2013 总结

作者:刘峥

2013年04月17日,Ext4 社区的开发者举行了一个讨论会。主要讨论目前 Ext4 文件系统中出现的问题及解决方法,以及后续的开发计划。本文章汇总了本次会议的内容。

在这次会议中,主要讨论了如下内容(每个话题中讨论的内容包括但不限于话题本身):

  1. write stall 问题
  2. 3.10 merge window 的相关情况
  3. 关于 Ext4 stable/long-term tree 的维护
  4. extent tree layout 修改
  5. bigalloc 特性的改进
  6. Online Fsck 特性的开发
  7. data=guarded 和文件系统延迟问题的优化
  8. 不同挂载参数的选择
  9. Ext4 针对不同设备的优化

与会人员:

  • Ted Ts'o (Ext4/JBD2 Maintainer, Google)
  • Jan Kara (EXT2/3/JBD Maintainer, SUSE)
  • Eric Sandeen (Red Hat)
  • Mingming Cao (Oracle)
  • Tao Ma (Tao Bao)
  • Lukas Cerner (Red Hat)
  • Zheng Liu (Tao Bao)
  • Darrick Wong (Oracle)
  • Mel Gorman (SUSE)
  • Daniel Phillips

1. write stall 问题

这一问题最初是由 MM 内核开发者 Mel Gorman 报告的,他在测试内存管理的补丁时,发现 Ext4 文件系统的交互响应比较差,延迟很高。通过观察发现是由于 do_get_write_access() 函数中会阻塞在 lock_buffer() 上,造成延迟较大。

Ted Ts'o 提出了两种解决方案:

1) 在调用 do_get_write_access() 时避免 lock_buffer;

2) 整体修改 JBD2,自己管理 buffer_head,从而降低延迟。

由于第二种方案太过复杂,短期内很难完成,所以目前打算先优化 do_get_write_access() 函数来降低延迟。同时,在刷新 metadata 时,通过加入 REQ_* 标记来避免优先级反转问题,提高响应速度。

 

2. 3.10 merge window 的相关情况

最近马上要开始新一轮的 merge window 了,所以 Ted 说明了一下目前的进展,他目前还在进行各种测试。Jan Kara 说他通过 xfstests 测试发现 data=journal 模式下第68项测试失败。Ted 则抱怨了一下 xfstests 没有支持 local group,造成每次测试都要手工指定测试项目。

Lukas 讨论了他关于优化 invalidatepage() 的补丁,Jan 表示会 review 代码。Ted 则说这个 merge window 可以考虑把 vfs 层的补丁先合并进来,下个 merge window 再解决 Ext4 专门的补丁。

Jan 则讨论了他关于优化 Ext4 writepage 路径的补丁,Ted 的建议是留到下一个 merge window 再合并。

 

3. 关于 Ext4 stable/long-term tree 的维护

Ted 对于 stable/long-term tree 的维护工作的态度是,目前他没有时间和精力来单独维护一个这样的 tree。目前,对于 Ext4 文件系统来说,如果需要使用较为稳定的版本,可以的选择是 linux stable tree。因为目前所有有意义的补丁会被抄送给 stable@vger.kernel.org,由 stable tree 对应的维护者来进行维护。当然,如果一些补丁不能够简单的直接打到 stable tree 上,则该补丁将不会包含在相应的 stable tree 中。

 

4. extent tree layout 修改

目前 Ext4 中 extent 存储的物理磁盘块的长度是 48 位,所以,可以将其扩展为 64 位以支持更大的磁盘分区。Ted 表示如果可以扩展到 64 位当然是最好的,但是这是一个长期的工作,目前还没有明确的需求需要搞这么大的文件系统。

目前 Ted 认为对于 Ext4 文件系统更为重要的事情是如下几个:

  • 解决 unwritten extent conversion 的问题,从而彻底实现 dioread_nolock;
  • 对 extent tree/map_blocks 函数进行重构;
  • mballoc 代码的重构和改进,包括 buddy bitmap 被很快回收的问题;

 

5. bigalloc 特性的改进

目前淘宝在使用 bigalloc 的过程中发现该特性还有一些不足,比如在使用 cluster (默认64k) 作为磁盘分配的单位时,对于小文件的存储,空间开销偏大。所以淘宝的想法是希望能够某几个 block group 按照 block size 来分配文件,剩下的 block group 按照 cluster size 来分配。这样可以尽量减少小文件对磁盘空间的占用。Ted 给出的建议是可以考虑指定一个参数,在格式化的时候,指定前面多少个 block group 通过 block size 来分配。这样做相对比较简单;另外一种更为简单的方法是将磁盘分成两个分区,分别按 block size 和 cluster size 来进行格式化,从而解决这一问题。

 

6. Online Fsck 特性的开发

这一需求也是淘宝目前遇到的实际问题。由于数据库等系统需要尽可能的在线提供服务,所以我们希望能够尽可能的缩短宕机后的启动时间。所以,如果可以实现 online fsck 的功能,则可以尽可能的缩短系统启动的时间,同时保证文件系统不被破坏。目前已知的可以进行 online fsck 的文件系统是 zfs, ffs, btrfs。Ted 给出的建议是可以考虑在分配磁盘块的时候在相应的 block group 上添加相应的标记,表明这个 block group 正在进行磁盘块的分配,在出现宕机后,这个 block group 的数据只进行读操作,所有写操作都会被映射到其他的 block group 中。这样可以尽可能的保证文件系统的一致性。

 

7. data=guarded 和文件系统延迟问题的优化

data=guarded 模式最早是 Chris Mason 针对 ext3 fsync 延迟过大提出的一种日志模式。但是后来由于 ext4 中引入延迟分配 (delalloc) 特性而没有再继续开发,也没有被合并进 upstream kernel。这次提出这个话题,主要是由于淘宝在部署 ext4 的过程中遇到了很多延迟问题。在讨论延迟问题的过程中,Ted 提出了一个长远的改进计划,即通过使用 extent status tree 在内存中进行磁盘块的分配,在 end_io 中再创建日志并修改元数据提交。这样可以极大地缩短日志的持有时间,从而尽可能的避免由于日志提交造成文件系统操作的延迟。同时 Ted 还建议减少延迟的方法是尽可能提前将文件预分配出来,同时尽量将文件的元信息保存在内存中。

 

8. 不同挂载参数的选择

这个话题主要是 Red Hat 和 SUSE 的开发者提出的,目的是减少 Ext4 测试环节的压力,同时由于 Linux 发行版陆续使用 Ext4 内核模块来处理 Ext2/3 文件系统,需要在内核中添加检查代码来确保 Ext2/3 文件系统在使用 Ext4 内核模块时的正确性。

其中比较重要的几个挂载参数是是:

  • indirect-based/extent-based 文件的支持;
  • async_journal_commit参数(该参数将被标记为危险,可能造成数据丢失);
  • data=journal 与 delalloc 的互斥问题

 

9. Ext4 针对不同设备的优化

这一话题主要是围绕目前文件系统开发的优化方向来进行讨论。由于 ARM 处理器在服务器领域的使用,文件系统即需要考虑高端硬件设备的优化,同时还要兼顾这类低端设备的优化。针对高端设备,文件系统可以多使用些资源(如内存资源)来获取更好的性能;同时针对 ARM 这类内存较小的设备,可以减小资源的使用,同时提供尽可能好的性能。

Ted 表示目前 Google 针对 e2fsck/mke2fs 工具是有一些优化的,并且已经放到了 upstream 的 e2fsprogs 中,但是并没有在内核代码中针对不同设备进行优化的想法。同时 Ted 表示目前可能更需要考虑针对 eMMC 设备的优化问题。

 

根据本次 Ext4 workshop,后续 Ext4 文件系统的开发主要包括:

  • extent tree 代码重构
  • map_blocks 函数代码重构
  • do_get_write_access() 优化,解决 write stall 问题(目前 Ted 已经将补丁发出并合并进ext4 dev 分支)
  • 使用 extent status tree 来优化磁盘块分配,减小延迟
  • 修改 extent tree layout 支持更大的磁盘
  • mballoc 代码的重构和优化

关于此前使用 extent status tree 实现 range locking 的问题。由于 Jan Kara 已经开始在 VFS 层实现一套通用的 range locking,因此目前与 Ted, Jan 讨论的结果是暂时先不在 Ext4 中单独实现一个 range locking 了。

未来一段时间,Ext4 的开发将主要集中在已有问题的解决,性能的调优和代码的重构上。暂时不会有新的供用户使用的新特性。

修复ext4日志(jbd2)bug

[原写于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来帮助我们在线升级内核。