Log把磁盘写满了会有什么后果

背景

最近在测试环境灰度时，业务反应服务无响应，然后马上摘除节点恢复业务。

到测试机器检查，发现进程存在，日志正常。

printf "stats\r\n"|nc localhost 10101

测试端口发现命令卡住，大约10s才回复。

syscall:write耗时

df -h发现磁盘写满，然而磁盘满会使写磁盘这么慢吗？

用strace查看每次write耗时

img

每次write耗时250ms+...有点长。

修改代码，把_log函数体注释，重新编译发现服务恢复正常。

在印象中，感觉磁盘满不可能会导致写文件这么慢啊，有啥问题呢？

又找了一台新的机器，写了小程序先把磁盘写满，然后启动同样的程序，测试发现一切正常

img

这就很有趣了，那么问题在哪呢？

ext4

uname -r发现没有问题的内核版本是3.10.0-229.el7.x86_64，有问题的版本是2.6.32-431.11.2.el6.toa.2.x86_64

df -T发现文件系统都是ext4，怀疑可能是ext4文件系统某些机制导致的

使用perf stat查看所有ext4文件系统的trace event

sudo perf stat -e "ext4:*" -p 23488 sleep 10

1. 有问题的机器

   

   img
2. 没问题的机器

   

   img

发现ext4的执行路径差异很大，然后同时trace ext4和syscall:write

sudo perf stat -e "syscalls:sys_enter_write,ext4:*" -p 23488 sleep 10

img

试了几次发现syscall:write和ext4:ext4_da_write_begin次数完全一样，这说明每次write都会调用ext4的ext4_da_write_begin，但是接下来的执行逻辑就不一样了。

内核源码

翻内核的源码发现，函数ext4_da_write_begin在3.10和2.6差别很多，用systemtap脚本调试N久，尝试复原ext4_da_write_begin不同的路径

static int ext4_da_write_begin(){
    /*省略*/
	if (ret == -ENOSPC && ext4_should_retry_alloc(inode->i_sb, &retries))
		goto retry;
out:
	return ret;
}

看到在写满ENOSPC的错误发生时，ext4_should_retry_alloc函数的嫌疑很大，怀疑是触发了不同的逻辑导致低版本内核频繁的重试

用脚本trace发现在函数ext4_should_retry_alloc里有差异，有问题的机器会去频繁jbd2_journal_force_commit_nested，而没问题的机器直接return 0

int ext4_should_retry_alloc(struct super_block *sb, int *retries)
{
	if (!ext4_has_free_blocks(EXT4_SB(sb), 1) ||
	    (*retries)++ > 3 ||
	    !EXT4_SB(sb)->s_journal)
		return 0;

	jbd_debug(1, "%s: retrying operation after ENOSPC\n", sb->s_id);

	return jbd2_journal_force_commit_nested(EXT4_SB(sb)->s_journal);
}

stap脚本

global joural
global ext4

probe module("ext4").function("ext4_da_write_begin").call {
    ext4++;
}

probe module("jbd2").function("jbd2_journal_force_commit_nested").call {
    joural++;
}

probe module("ext4").function("ext4_has_free_clusters").return {
   printf("%x\n",@cast($sb->s_fs_info,"ext4_sb_info")->s_journal);
}

probe timer.s(1), end {
    ansi_clear_screen();
    printf("%10s %10s\n","ext4_write_begin","jbd2_journal_force_commit_nested");
    printf("%10d %10d\n",ext4,joural);
}

1. 有问题的机器

   

   img
2. 没问题的机器

   

   img

继续往下看

int ext4_has_free_blocks(struct ext4_sb_info *sbi, s64 nblocks)
{
    /* 省略 */
	/* Hm, nope.  Are (enough) root reserved blocks available? */
	if (sbi->s_resuid == current_fsuid() ||
	    ((sbi->s_resgid != 0) && in_group_p(sbi->s_resgid)) ||
	    capable(CAP_SYS_RESOURCE)) {
		if (free_blocks >= (nblocks + dirty_blocks))
			return 1;
	}

	return 0;
}

发现在函数ext4_has_free_blocks中会判断是否会有空闲块，决定是不是重试，对比3.10的代码，在3.10中的函数是

static int ext4_has_free_clusters(struct ext4_sb_info *sbi,
				  s64 nclusters, unsigned int flags)
{
    /* 省略 */
	/* No free blocks. Let's see if we can dip into reserved pool */
	if (flags & EXT4_MB_USE_RESERVED) {
		if (free_clusters >= (nclusters + dirty_clusters))
			return 1;
	}

	return 0;
}

发现在判断逻辑上的不同，在3.10里，函数ext4_has_free_clusters调用时，flags传入0，所以不考虑root用户的预留空间，而在2.6里会判断用户是否是root用户，假如是root用户，那么在判断空闲块是否够用时会加上root用户的预留空间。

写个脚本看一下free_blocks，nblocks，dirty_blocks,root_blocks分别是多少

probe module("ext4").function("ext4_has_free_blocks") {
  printf("free: %d dirty: %x nblocks: %d root: %d\n",$sbi->s_freeblocks_counter->count,$sbi->s_dirtyblocks_counter->count,$nblocks,$sbi->s_es->s_r_blocks_count_hi<<32|$sbi->s_es->s_free_blocks_count_lo);
}

img

root用户的判断逻辑是free > nblocks + dirty，是true，所以一直在重试

非root用户的判断逻辑是free > nblocks + dirty + root，是false，所以不会重试

验证

这应该是问题所在了，那么也很好验证，在低内核版本上只有root用户才有权限使用预留空间，那么我们用其他用户启动程序，应该就没有这个问题了。

img

重新用非root用户启动程序，strace查看，完全正常。

总结

那么这个问题就是由于低版本的内核文件系统某些缺陷导致的，但是线上的内核版本不一，假如由于某些问题或者其他进程把磁盘刷爆，那么很有可能导致服务不可用。

预防措施：

1. 对日志增加监控，防止出现日志把磁盘刷爆的情况

2. 尽量用非root用户启动进程