背景
ossfs是一个可以将OSS的Bucket挂载到本地文件系统的工具，用户可以像操作本地文件一样（ls/cat/stat）操作OSS的Object。
随机Fail
在跑ossfs的测试时，一个CASE偶尔会fail，确认原因时，发现这个CASE的逻辑非常简单：
function test_truncate_file {
echo "Testing truncate file ..."
# Write a small test file
echo "${TEST_TEXT}" > ${TEST_TEXT_FILE}
# Truncate file to 0 length. This should trigger open(path, O_RDWR | O_TRUNC...)
: > ${TEST_TEXT_FILE}
# Verify file is zero length
if [ -s ${TEST_TEXT_FILE} ]
then
echo "error: expected ${TEST_TEXT_FILE} to be zero length"
exit 1
fi
rm_test_file
}CASE分为3步：
- 写一点东西到文件
test-file - 通过bash中的重定向命令
: > test-file将文件变成空 - 检查文件的size是0
失败发生在第3步，有时文件的size不是0！How can?
重现
于是决定用简单的方法重现：
- 挂载ossfs到
/tmp/ossfs - 用一个脚本反复地跑，直到fail
i=0
file=/tmp/ossfs/test-cache
while echo 'hello world' > $file \
&& : > $file \
&& [ ! -s $file ] \
; do echo $i && i=$((i+1)); done果然很容易就重现了。
第一个Cache
开启ossfs的debug模式：
stdbuf -oL -eL ossfs gems /tmp/ossfs -ourl=http://oss-test.aliyun-inc.com \
-f -d -d -s注意上面的stdbuf -oL -eL可以让程序的输出是line buffered，避免有些log没有及时打出来的情况。（ 这个很关键 ）-f -d -d -s让ossfs输出debug日志。
再运行重现脚本，出现fail时，ossfs的输出是：
unique: 5325, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 11713
open flags: 0x8201 /test-cache
[INF] s3fs.cpp:s3fs_open(2007): [path=/test-cache][flags=33281]
unique: 5326, opcode: REMOVEXATTR (24), nodeid: 2, insize: 53, pid: 11713
removexattr /test-cache security.ima
[INF] s3fs.cpp:s3fs_removexattr(3200): [path=/test-cache][name=security.ima]
unique: 5326, error: -61 (No data available), outsize: 16
unique: 5327, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 11713
flush[5]
[INF] s3fs.cpp:s3fs_flush(2127): [path=/test-cache][fd=5]
[INF] fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=5]
unique: 5327, success, outsize: 16
unique: 5328, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 11713
flush[5]
[INF] s3fs.cpp:s3fs_flush(2127): [path=/test-cache][fd=5]
[INF] fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=5]
unique: 5328, success, outsize: 16
unique: 5329, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0
unique: 5330, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 11713
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(797): [path=/test-cache]
release[5] flags: 0x8001
[INF] s3fs.cpp:s3fs_release(2180): [path=/test-cache][fd=5]
NODEID: 2
[INF] cache.cpp:DelStat(404): delete stat cache entry[path=/test-cache]
unique: 5330, success, outsize: 144
unique: 5331, opcode: GETXATTR (22), nodeid: 2, insize: 68, pid: 11713
getxattr /test-cache security.capability 20其中XATTR相关的日志可以忽略。上面的log中看到：
- 第5325次操作是open(O_TRUNC)，对应的是
: > $file这句 - 之后的flush和release是关闭文件后的操作
- 第5330次的getattr操作对应的是判断文件size为0:
[ ! -s $file ]
注意到getattr下面并没有发送HTTP HEAD请求向OSS获取文件的信息，从代码中可以看到，ossfs中有一个StatCache，用户缓存文件的Stat信息，这样能够避免频繁地发送HEAD请求以获取文件的size等meta信息。
src/s3fs.cpp
static int get_object_attribute(...)
{
// ...
// Check cache.
strpath = path;
if(overcheck && string::npos != (Pos = strpath.find("_$folder$", 0))){
strpath = strpath.substr(0, Pos);
strpath += "/";
}
if(pisforce){
(*pisforce) = false;
}
if(StatCache::getStatCacheData()->GetStat(strpath, pstat, pheader, overcheck, pisforce)){
return 0;
}
if(StatCache::getStatCacheData()->IsNoObjectCache(strpath)){
// there is the path in the cache for no object, it is no object.
return -ENOENT;
}
// ...
}所以这次getattr是直接从ossfs的stat cache中取的。在代码中加入更多的debug信息后看到，这次getattr拿到的size是12，就是上次操作的size。为什么cache没有被更新呢？
从代码中看到在s3fs_release中进行了DelStat的操作：
static int s3fs_release(const char* path, struct fuse_file_info* fi)
{
S3FS_PRN_INFO("[path=%s][fd=%llu]", path, (unsigned long long)(fi->fh));
// [NOTICE]
// At first, we remove stats cache.
// Because fuse does not wait for response from "release" function. :-(
// And fuse runs next command before this function returns.
// Thus we call deleting stats function ASSAP.
//
if((fi->flags & O_RDWR) || (fi->flags & O_WRONLY)){
StatCache::getStatCacheData()->DelStat(path);
}同时，还有一段颇长的注释。可以看到是由于fuse的一个known issue，导致s3fs_release函数是被异步调用的，也就是说发生了现在的时序：
T1 T2
echo 'hello world' > $file put stat into cache
: > $file
getattr
release(delete stat from cache)由于cache没有及时被删掉，导致第3步的操作获取到的stat还是第1步的操作放到cache中的结果。
尝试修复
既然在release中DelStat太晚了，那么将它提前到flush中总可以了吧？于是做了下面的fix：
--- a/src/fdcache.cpp
+++ b/src/fdcache.cpp
@@ -1297,6 +1297,8 @@ int FdEntity::NoCacheCompleteMultipartPost(void)
int FdEntity::RowFlush(const char* tpath, bool force_sync)
{
+ StatCache::getStatCacheData()->DelStat(path.c_str());
+
int result;
S3FS_PRN_INFO3("[tpath=%s][path=%s][fd=%d]", SAFESTRPTR(tpath), path.c_str(), fd);修复后再跑，发现还是会随机fail。
第二个Cache
这次fail时的log更加奇怪：
unique: 671, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 3641
open flags: 0x8201 /test-cache
[INF] s3fs.cpp:s3fs_open(2006): [path=/test-cache][flags=33281]
unique: 672, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 3641
flush[4]
[INF] s3fs.cpp:s3fs_flush(2126): [path=/test-cache][fd=4]
[INF] fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=4]
unique: 672, success, outsize: 16
unique: 673, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0
release[4] flags: 0x8001
[INF] s3fs.cpp:s3fs_release(2179): [path=/test-cache][fd=4]
[INF] cache.cpp:DelStat(404): delete stat cache entry[path=/test-cache]
[INF] fdcache.cpp:GetFdEntity(1779): [path=/test-cache][fd=4]
unique: 673, success, outsize: 16注意到最后一步并不是getattr。为什么[ ! -s $file ]这句话没有对应的getattr呢？手动执行stat -c %s /tmp/ossfs/test-cache，发现第执行一次都会增加一条log：
unique: 674, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 3645
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(796): [path=/test-cache]
[INF] curl.cpp:HeadRequest(2141): [tpath=/test-cache]
NODEID: 2
unique: 674, success, outsize: 144
unique: 675, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 3648
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(796): [path=/test-cache]
NODEID: 2
unique: 675, success, outsize: 144连续两次执行的结果如上，可以看到第1次执行的时候由于Cache里没有，发生一次HEAD请求，第二次的时候直接从Cache里读出来。
循环执行100遍：for i in $(seq 100); do stat -c %s /tmp/ossfs; done，
发现并没有增加100条log！而只增加了1条！
为什么手动执行每次都能触发，但是循环就不行？猜测原因可能是：
- fuse会对请求作group，短时间内的100次请求被group处理了
- 文件系统会对文件的stat进行cache
针对第1条猜测，去看libfuse的代码，并没有发现有group处理的逻辑。
针对第2条猜测，请教了内核和存储相关的同学，得到的答案是即使有cache（page cache)也不应该这么快就过期。
于是再去看fuse的代码，一个偶然的机会，看到fuse居然有一个attr_timeout，默认的时间是1s！上面的问题终于有了答案：fuse对attr有cache。
本以为到此为止，问题都解决了。但是fuse的这个解释说只要文件操作是经过内核的，attr_timeout不为0时正确性是保证的：对这个文件进行了相关的操作时，内核会invalidate这个cache（使cache失效）。
那么为什么truncate文件这个操作没有invalidate这个cache呢？突然想到有没有可能还是release的问题，要到release时才会invalidate这个cache，而release可能被异步执行。皓然认为不应该：为什么要到release才会去更新？
而我用C语言做了一个实验：用O_TRUNC的方式打开一个有内容的文件，然后就sleep，并不关闭它。另外一边用stat去看这个文件的大小，结果是open后文件的size就变成0了。
所以应该不是release的问题。
Kernel的问题
为了查清这个cache到底什么时候被失效，决定去看一看kernel的代码。我出问题的系统是CentOS6.5，内核是2.6.32版本的，于是去这里下载了2.6.32的代码，看到fs/fuse/file.c中：
// fs/fuse/file.c
void fuse_finish_open(struct inode *inode, struct file *file)
{
struct fuse_file *ff = file->private_data;
struct fuse_conn *fc = get_fuse_conn(inode);
if (ff->open_flags & FOPEN_DIRECT_IO)
file->f_op = &fuse_direct_io_file_operations;
if (!(ff->open_flags & FOPEN_KEEP_CACHE))
invalidate_inode_pages2(inode->i_mapping);
if (ff->open_flags & FOPEN_NONSEEKABLE)
nonseekable_open(inode, file);
if (fc->atomic_o_trunc && (file->f_flags & O_TRUNC)) {
struct fuse_inode *fi = get_fuse_inode(inode);
spin_lock(&fc->lock);
fi->attr_version = ++fc->attr_version;
i_size_write(inode, 0);
spin_unlock(&fc->lock);
fuse_invalidate_attr(inode);
}
}从这里看到，如果以O_TRUNC的方式open的话，是立即就会失效cache的。那为什么问题还会出现呢？我只能怀疑上面的if (fc->atomic_o_trunc && (file->f_flags & O_TRUNC)) {中有某个条件不满足：
-
fc->atomic_o_trunc，翻libfuse的代码，看到这个值默认是true的，而
通过-oatomic_o_trunc参数挂载，问题也依然存在 -
file->f_flags中没有包含O_TRUNC，通过log可以看到open的flags是0x8201，而O_TRUNC是0x0200
上面的两个条件都是满足的，为什么fuse_invalidate_attr没有生效呢？为了搞清楚这个问题，我决定在fuse的代码中打印一些调试信息，然后重新编译一个fuse模块。
编译内核模块
得益于当初搞cubieboard时编译无线网卡驱动，编译内核模块应该也不难。好在CentOS的wiki还是很详细，参考下来很容易就能编译好。
make oldconfig
make prepare
make modules_prepare
make M=fs/fuse当我下载完CentOS-6.5的内核源码正准备对fuse模块稍加修改时，一个尴尬的事情发生了：fs/fuse/file.c中并没有fuse_invalidate_attr这一段：
void fuse_finish_open(struct inode *inode, struct file *file)
{
struct fuse_file *ff = file->private_data;
struct fuse_conn *fc = get_fuse_conn(inode);
struct fuse_inode *fi = get_fuse_inode(inode);
if (ff->open_flags & FOPEN_DIRECT_IO)
file->f_op = &fuse_direct_io_file_operations;
if (!(ff->open_flags & FOPEN_KEEP_CACHE))
invalidate_inode_pages2(inode->i_mapping);
if (ff->open_flags & FOPEN_NONSEEKABLE)
nonseekable_open(inode, file);
/* file might be required for fallocate */
spin_lock(&fc->lock);
if (S_ISREG(inode->i_mode) && (file->f_mode & FMODE_WRITE))
list_add(&ff->write_entry, &fi->write_files);
spin_unlock(&fc->lock);
}原来如此！ 而我手动添加这几行代码后再编译&替换掉fuse模块，一切正常！
modprobe -r fuse
insmod fs/fuse/fuse.ko进一步blame发现，这个patch是在2010年的时候进的，是在2.6.32之后进的，而CentOS-6.5的内核并没有包含这个patch。
stat & lstat
在测试中还发现一个现象，使用stat -c %s $file和[ ! -s $file ]这两个方式判断文件的size为0，重现的概率不一样。后者重现的概率要高一些。通过strace发现这两个方法几乎没有区别，一个调用stat，一个调用lstat。
后来想明白了，原因是前者比后者慢，使用后者时有更大的概率release还没有调用完。而release中包含了fuse_invalidate_attr的逻辑。
stat -c %s $file需要创建一个进程（来运行stat），而[ ! -s $file ]是在和bash同样的进程中进行的，所以会更快。
