DongHao: 12 2012存档
上周四在杭州做了一个flashcache的讲座，主要介绍原理和近几个月我的改造工作，PPT如下，供大家参考：
生产上报来了内核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 <tytso@mit.edu>
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" <tytso@mit.edu>
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内核是有这个问题的，大家多小心。
======
本来想用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，不睡。
没想到netoops加show_state()调试死锁这么方便，当然，难的是找到快速重现bug的办法。
昨天下午做了一个组内分享，讲了一下Linux的块设备层，PPT很简单，仅供参考。
前天，我在上网。
老婆：看啥哩？
我：看二手服务器
老婆：咋地？又对服务器感兴趣了
我：给我买台服务器吧，八核高配，才一千多
老婆：（怒）今年已经给你买了ARM板子了，明年再说！
今天早上。从电梯下来，几个老奶奶在讨论白天暖气不足的事情。
老婆：好像这新修的天然气供暖不行啊，白天大家都说冷
我：买台服务器吧，跑起来温度可高了
老婆：......
我：同事自己攒的AMD CPU的服务器，跑起来滚烫的，冬天家里可暖和了
老婆：你不是有ARM板吗？跑它就行了呗
我：ARM不够热啊，我使劲编译程序，跑压力，板子依然冰凉的呀
前一阵子买了一块Cubieboard，就是类似RaspberryPi的ARM板子，之所以选Cubieboard而不是RaspberryPi是因为Cubie的配置更高——1Ghz的ARM核（全志A10），1G的DDR内存，4G的NAND，还带一个SATA口（做为一个靠廉价存储混饭吃的loser，我热爱SATA口）。
板子拿到手，跟照片一模一样，Tom Cubie（Cubieboard的设计者）同学不欺我也。可回收的纸盒子也很可爱。
开始是用wiki上提供的Buildroot方法把编译好的image烧到板子上的NAND里，可以成功启动到Linux 3.4.5 kernel，字符终端，可以联网，但是毕竟系统工具都是用busybox攒的，太少，不够方便，也没有包管理工具。此root系统带有一个CedarXPlayer工具，可以看1080p的视频，即使是高清的rmvb都很流畅（这小板子确实厉害），但是，这个神奇的CedarXPlayer工具不支持快进快退甚至连暂停都不支持，而且退出播放时需要用Ctrl + c，纯属测试工具。
所以，还是改用SD卡启动，论坛上有人提供了BerryBoot，用它可以直接把linaro（可以理解为ARM版的ubuntu）装到SD卡上，能成功进到图形界面，只是分辨率有点低。但此时我再用vlc看rmvb的时候就变得特别卡了，想来是跟显卡驱动有关系，于是按论坛上的说法装了显卡驱动，但还是不好使，只好发邮件问Tom Cubie，他非常耐心的回答了我：
CedaX 是Allwinner自己的一个框架，http://linux-sunxi.org/CedarX
Linux下媒体播放你可以看看这个
http://linux-sunxi.org/VLC
我按照文档里的步骤装了VLC，居然不出图像。嗯，我还需要好好琢磨琢磨。
Cubieboard不光是能做高清播放机，那个sata口加上板子上的 2 pin 的电源口，完全可以接一个2.5寸的笔记本硬盘（或者有钱的话，一个SSD）。想想看，一个5V电压2A电流的ipad充电器，就可以带动一个基于ARM的NAS（Cubieboard加一块2.5寸硬盘），才10瓦功耗的NAS呀，放在家里，可以下个BT，做个共享，看个电影，还是很有优势的。
同事何燕峰送了我一个小机箱，我便把Cubieboard和一个3.5寸的硬盘（实在找不到2.5寸的，3.5寸的硬盘光靠Cubieboard上的2 pin电源口是带不动的，要另外供电，因为2.5寸硬盘只需要5V的电压，而3.5寸硬盘需要12V和5V两种电压）一起放进机箱里，还挺合身：
猜猜Cubieboard的设计者Tom Cubie同学多大？2010年的本科毕业生。人家都有自己的事业了。想想我自己，三十好几的人了，还在给人修bug、做测试、调性能，还不招人待见，真是惭愧。
我以后要多向Tom Cubie同学学习。
