背景
目前线上的某几组Redis Group
开启了AOF
做数据持久化,使用了默认的appendfsync
配置,即everysec
。前段时间某次操作时,向某一个Redis Master A
发起slaveof
请求,导致这台机器上的Redis Master A
和另外一个Redis Master B
出现了服务不可用。
现象
两台Redis
实例都有十几秒种服务不可用,而且都出现如下错误日志:
|
|
按照这个日志的提示,this may slow down Redis
,可能会拖慢Redis
服务,但是AOF fsync
是异步线程执行,应该不会对正常的工作线程产生影响?
带着这个问题,做了以下实验。
场景模拟
问题可以抽象为磁盘慢对Redis
实例的影响,模拟工具方面,甘大神推荐了Device Mapper
里面的工具: dm-delay。
实验环境
os: Debian 3.16.36-1+deb8u2
gcc: 4.9.2
redis: 2.8.21
kernel-source: linux-3.16.39
详细步骤
生成本地文件local-device
,然后映射成本地块设备/dev/loop0
|
|
使用dmsetup
设置块设备的延时
设置写延时为5s
|
|
脚本block-dev.sh
的内容如下
|
|
挂载到目录dir-on-delayed-device
|
|
查看挂载之后的结果
|
|
启动Redis
使用上面的dir-on-delayed-device
作为工作目录dir
Redis配置如下:
|
|
启动
|
|
尝试重现错误
使用routine.sh
脚本向Redis
中写入数据,并统计响应时间,响应时间大于300ms
的,就打印日志;其余的快速闪过。
|
|
脚本routine.sh
内容如下:
|
|
Redis
的日志里面出现了和之前相同的错误:
|
|
每隔2s
会打印一次内容
另外从routine.sh
的运行结果可以看到:
|
|
慢请求出现的时间间隔有些规律,但也没有非常严格的规律;出现的间隔大部分是25s
,也有15s
、20s
的;慢请求的响应时间大部分在8s
左右,也有4s
、10s
的。
产生异常日志、影响服务,这两个问题在上面的实验中都出现了,下面来尝试解释上面实验中出现的现象。
现象解释
有以下三个问题需要回答:
- 为什么是每
2s
打印一次错误日志this may slow down Redis
- 为什么会出现慢请求
- 为什么慢请求的响应时间和出现的间隔是上面那样
this may slow down Redis
先贴Redis
相关的代码src/aof.c
:
|
|
关注在appendfsync
是AOF_FSYNC_EVERYSEC
这个策略时的系统的表现:
当AOF_FSYNC_EVERYSEC
这个策略时,会先检查有没有线程正在做fsync
,状态存储在变量sync_in_progress
中,然后做以下判断
- 如果有,而且这是第一次被
postpone
的调用,记录server.aof_flush_postponed_start
, 返回 - 如果有,而且
postpone
的时间不足2s,返回 - 如果有,而且已经超过2s没执行完了,会增加记数
server.aof_delayed_fsync
打印日志,Asynchronous AOF fsync is taking too long (disk is busy?)
并仍然去执行write
对于AOF_FSYNC_EVERYSEC
来说,这个函数的末尾会判断是否调用aof_background_fsync
,同一时
刻只能有一个异步线程做fsync
这段代码可以解释为什么是每隔2s
打印一次日志。
慢请求
出现慢请求的原因是这个问题的关键。Redis作者antirez
就上述问题也写过一篇类似的博文。
问题可以简化为fsync
操作会不会阻塞write
操作。做下面一个实验,起两个线程,一个线程调用write
,另外一个线程调用fsync
,看write
操作会不会被阻塞。
|
|
fsync-test.cc
的内容见此处。
实验打印出来的日志为:
|
|
日志格式为:时间戳,write
或者fsync
操作的序号,打印信息。
试验结果表明:fsync
确实可能阻塞write
。
查到这里有些卡壳了,请教了周围一些同学。浅小奕说,瞎猜不如看代码
。内核组同学亚小方
指出这个行为应该和具体文件系统实现是有关系的。
查看了下刚才测试目录使用的文件系统类型:
|
|
先看fsync
系统调用的实现,位于文件fs/sync.c
中:
|
|
最终会调用vfs_fsync_range
:
|
|
这里可以看到,调用了file->f_op->fsync
,ext2
相关的实现位于文件fs/ext2/file.c
中:
|
|
generic_file_fsync
的实现,位于文件fs/libfs.c
中:
|
|
会对inode->i_mutex
进行加锁,对于fdatasync
,可能会不需要访问设备,跳出加锁区域:
|
|
那么,write
操作中是否有对inode->i_mutex
加锁的过程呢?write
操作会调用函数generic_file_write_iter
,位于文件mm/filemap.c
中:
|
|
也会对inode
进行加锁。
到这里,已经重现了慢请求
,并且从代码层面上说明了慢请求
出现的原因了。
上述的实验中,fsync
每次调用会耗时15s
,fsync
开始后5s
,write
操作开始被阻塞;
假设fsync
会有3个阶段A、B、C
,每阶段耗时5s
(设置的设备delay
是5s
),但是只有B
阶段会阻塞write
,A、C
是对write
没影响的,才会出现上面的情况。
B
阶段从上述代码中可以看到是__generic_file_fsync
中:
|
|
那么,A
阶段和C
阶段,fsync
都是做了什么事情呢?
使用systemtap
脚本拿到各个阶段的耗时,脚本内容类似于:
|
|
分别拿到func0
/func1
/func2
的耗时,过程比较人肉:(
得到结论:A
阶段是filemap_write_and_wait_range
,C
阶段是blkdev_issue_flush
。
到些,使用fsync-test
实验产生的数据就都可以解释了。
慢请求
的响应时间和出现的间隔
Redis
的测试中慢请求的响应时间和出现间隔不太规律:
慢请求出现的时间间隔有些规律,但也没有非常严格的规律;出现的间隔大部分是
25s
,也有15s
、20s
的;慢请求的响应时间大部分在8s
左右,也有4s
、10s
的。
这个数据目前没有办法完全解释清楚。和fsync-test
的区别在于,fsync-test
始终是写的同一个位置的四字节,Redis aof
是追加写;做aof
的过程中可能触发了系统的pdflush
来刷脏页,可能和这些有因素一定的关系。
参考
[1] https://www.kernel.org/doc/Documentation/device-mapper/delay.txt
[2] http://www.enodev.fr/posts/emulate-a-slow-block-device-with-dm-delay.html
[3] https://github.com/axboe/fio
[4] http://www.cnblogs.com/wuchanming/p/4820830.html
[5] http://www.thegeekstuff.com/2012/04/create-threads-in-linux
[6] http://blog.yufeng.info/archives/1283