第7章 Redis的噩梦：阻塞

文章目录

前言
1 发现阻塞
2.内在原因
- 2.1API或数据结构使用不合理
- - 2.1.1如何发现慢查询
  - 2.1.2.如何发现大对象
- 2.2 CPU饱和
- 2.3 持久化阻塞
- - 2.3.1fork阻塞
  - 2.3.2.AOF刷盘阻塞
  - 2.3.3.HugePage写操作阻塞
3 外在原因
- 3.1CPU竞争
- 3.2 内存交换

前言

Redis是典型的单线程架构，所有的读写操作都是在一条主线程中完成的。当Redis用于高并发场景时，如果出现阻塞，哪怕是很短时间，对于我们的应用来说都是噩梦。导致阻塞问题的场景大致分为内在原因和外在原因：

内在原因包括：不合理地使用API或数据结构、CPU饱和、持久化阻塞等。
外在原因包括：CPU竞争、内存交换、网络问题等。

1 发现阻塞

当Redis阻塞时，线上应用服务应该最先感知到，这时应用方会收到大量Redis超时异常，比如Jedis客户端会抛出JedisConnectionException异常。常见的做法是在应用方加入异常统计并通过邮件/短信/微信报警，以便及时发现通知问题。开发人员需要处理如何统计异常以及触发报警的时机。何时触发报警一般根据应用的并发量决定，如1分钟内超过10个异常触发报警。在实现异常统计时要注意，由于Redis调用API会分散在项目的多个地方，每个地方都监听异常并加入监控代码必然难以维护。这时可以借助于日志系统，如Java语言可以使用logback或log4j。当异常发生时，异常信息最终会被日志系统收集到Appender（输出目的地），默认的Appender一般是具体的日志文件，开发人员可以自定义一个Appender，用于专门统计异常和触发报警逻辑
在这里插入图片描述
以Java的logback为例，实现代码如下：

public class Redis Appender extends AppenderBase<ILoggingEvent> {
	// 使用guava的AtomicLongMap,用于并发计数
	public static final AtomicLongMap<String> ATOMIC_LONG_MAP = AtomicLongMap.create();
	static {
		// 自定义Appender加入到logback的rootLogger中
		LoggerContext loggerContext = (LoggerContext) 
		LoggerFactory.getILoggerFactory();
		Logger rootLogger = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME);
		ErrorStatisticsAppender errorStatisticsAppender = new 
		ErrorStatisticsAppender();
		errorStatisticsAppender.setContext(loggerContext);
		errorStatisticsAppender.start();
		rootLogger.addAppender(errorStatisticsAppender);
	}
	// 重写接收日志事件方法
	protected void append(ILoggingEvent event) {
		// 只监控error级别日志
		if (event.getLevel() == Level.ERROR) {
		IThrowableProxy throwableProxy = event.getThrowableProxy();
		// 确认抛出异常
			if (throwableProxy != null) {
				// 以每分钟为key，记录每分钟异常数量
				String key = DateUtil.formatDate(new Date(), "yyyyMMddHHmm");
				long errorCount = ATOMIC_LONG_MAP.incrementAndGet(key);
					if (errorCount > 10) {
						// 超过10次触发报警代码
					}
					// 清理历史计数统计，防止极端情况下内存泄露
					for (String oldKey : ATOMIC_LONG_MAP.asMap().keySet()) {
						if (!StringUtils.equals(key, oldKey)) {
						ATOMIC_LONG_MAP.remove(oldKey);
						}
					}
			}
		}
	}
}

开发提示：
借助日志系统统计异常的前提是，需要项目必须使用日志API进行异常统一输出，比如所有的异常都通过logger.error打印，这应该作为开发规范推广。其他编程语言也可以采用类似的日志系统实现异常统计报警。
应用方加入异常监控之后还存在一个问题，如果应用操作的是多个Redis节点（比如使用Redis集群），如何决定是哪一个节点超时还是所有的节点都有超时呢？这是线上很常见的需求，但绝大多数的客户端类库并没有在异常信息中打印ip和port信息，导致无法快速定位是哪个Redis节点超时。不过修改Redis客户端成本很低，比如Jedis只需要修改Connection类下的connect、sendCommand、readProtocolWithCheckingBroken方法专门捕获连接，发送命令，协议读取事件的异常。由于客户端类库都会保存ip和port信息，当异常发生时很容易打印出对应节点的ip和port，辅助我们快速定位问题节点。
除了在应用方加入统计报警逻辑之外，还可以借助Redis监控系统发现阻塞问题，当监控系统检测到Redis运行期的一些关键指标出现不正常时会触发报警。Redis相关的监控系统开源的方案有很多，一些公司内部也会自己开发监控系统。一个可靠的Redis监控系统首先需要做到对关键指标全方位监控和异常识别，辅助开发运维人员发现定位问题。如果Redis服务没有引入监控系统作辅助支撑，对于线上的服务是非常不负责任和危险的。这里推荐笔者团队开源的CacheCloud系统，它内部的统计监控模块能够很好地辅助工程师发现定位问题。
监控系统所监控的关键指标有很多，如命令耗时、慢查询、持久化阻塞、连接拒绝、CPU/内存/网络/磁盘使用过载等。当出现阻塞时如果相关人员不能深刻理解这些关键指标的含义和背后的原理，会严重影响解决问题的速度。

2.内在原因

Redis自身原因主要围绕以下几个方面排查：

API或数据结构使用不合理。
CPU饱和的问题。
持久化相关的阻塞。

2.1API或数据结构使用不合理

高并发的场景应该尽量避免在大对象上执行算法复杂度超过O（n）的命令。这是典型的不合理使用API和数据结构。如对一个包含上万个元素的hash结构执行hgetall操作。数据量比较大且命令算法复杂度是O（n），这条命令执行速度必然很慢。

2.1.1如何发现慢查询

Redis原生提供慢查询统计功能，slowlog len 获取慢查询的条数，执行slowlog get{n}命令可以获取最近的n条慢查询命令。慢查询本身只记录了命令执行时间，不包括数据网络传输时间和命令排队时间，因此客户端发生阻塞异常后，可能不是当前命令缓慢，而是在等待其他命令执行。需要重点比对异常和慢查询发生的时间点，确认是否有慢查询造成的命令阻塞排队。
发现慢查询后，开发人员需要作出及时调整。可以按照以下两个方向去调整：
1）修改为低算法度的命令，如hgetall改为hmget等，禁用keys、sort等命令。
2）调整大对象：缩减大对象数据或把大对象拆分为多个小对象，防止一次命令操作过多的数据。大对象拆分过程需要视具体的业务决定，如用户好友集合存储在Redis中，有些热点用户会关注大量好友，这时可以按时间或其他维度拆分到多个集合中。

2.1.2.如何发现大对象

Redis本身提供发现大对象的工具，对应命令：redis-cli-h{ip}-p{port}bigkeys。内部原理采用分段进行scan操作，把历史扫描过的最大对象统计出来便于分析优化，运行效果如下：

root@iZ2zec3etasicvrmg7svj0Z:/usr/local/bin# redis-cli -a password --bigkeys
Warning: Using a password with '-a' or '-u' option on the command line interface may not be safe.

# Scanning the entire keyspace to find biggest keys as well as
# average sizes per key type.  You can use -i 0.1 to sleep 0.1 sec
# per 100 SCAN commands (not usually needed).

[00.00%] Biggest hash   found so far '"user1"' with 2 fields
[00.00%] Biggest string found so far '"user:99:ratio"' with 3 bytes
[00.00%] Biggest list   found so far '"listkeyl"' with 6 items
[00.00%] Biggest string found so far '"k1"' with 11 bytes
[00.00%] Biggest zset   found so far '"cities:locations"' with 3 members
[00.00%] Biggest string found so far '"mybitmap"' with 13 bytes
[09.80%] Biggest string found so far '"pro"' with 39 bytes
[09.80%] Biggest zset   found so far '"topn"' with 5 members
[09.80%] Biggest set    found so far '"sk1"' with 3 members
[19.61%] Biggest hash   found so far '"uset:ztt"' with 3 fields
[29.41%] Biggest set    found so far '"myset"' with 21 members
[39.22%] Biggest string found so far '"users"' with 1261 bytes
[50.00%] Biggest hash   found so far '"user"' with 4 fields
[60.78%] Biggest zset   found so far '"myzset"' with 6 members
[60.78%] Biggest hash   found so far '"myhash"' with 6 fields
[70.59%] Biggest zset   found so far '"user:ranking:1_inter_2"' with 7 members
[81.37%] Biggest string found so far '"2016_05_01:unique:ids"' with 12304 bytes

-------- summary -------

Sampled 102 keys in the keyspace!
Total key length in bytes is 1027 (avg len 10.07)

Biggest   list found '"listkeyl"' has 6 items
Biggest   hash found '"myhash"' has 6 fields
Biggest string found '"2016_05_01:unique:ids"' has 12304 bytes
Biggest    set found '"myset"' has 21 members
Biggest   zset found '"user:ranking:1_inter_2"' has 7 members

14 lists with 50 items (13.73% of keys, avg size 3.57)
7 hashs with 23 fields (06.86% of keys, avg size 3.29)
57 strings with 13963 bytes (55.88% of keys, avg size 244.96)
0 streams with 0 entries (00.00% of keys, avg size 0.00)
12 sets with 51 members (11.76% of keys, avg size 4.25)
12 zsets with 44 members (11.76% of keys, avg size 3.67)

根据结果汇总信息能非常方便地获取到大对象的键，以及不同类型数据结构的使用情况。

2.2 CPU饱和

单线程的Redis处理命令时只能使用一个CPU。而CPU饱和是指Redis把单核CPU使用率跑到接近100%。使用top命令很容易识别出对应Redis进程的CPU使用率。CPU饱和是非常危险的，将导致Redis无法处理更多的命令，严重影响吞吐量和应用方的稳定性。对于这种情况，首先判断当前Redis的并发量是否达到极限，建议使用统计命令redis-cli-h{ip}-p{port}–stat获取当前Redis使用情况，该命令每秒输出一行统计信息，运行效果如下：

# redis-cli --stat
------- data ------ --------------------- load -------------------- - child -
keys mem clients blocked requests connections
3789785 3.20G 507 0 8867955607 (+0) 555894
3789813 3.20G 507 0 8867959511 (+63904) 555894
3789822 3.20G 507 0 8867961602 (+62091) 555894
3789831 3.20G 507 0 8867965049 (+63447) 555894
3789842 3.20G 507 0 8867969520 (+62675) 555894
3789845 3.20G 507 0 8867971943 (+62423) 555894

以上输出是一个接近饱和的Redis实例的统计信息，它每秒平均处理6万+的请求。对于这种情况，垂直层面的命令优化很难达到效果，这时就需要做集群化水平扩展来分摊OPS压力。如果只有几百或几千OPS的Redis实例就接近CPU饱和是很不正常的，有可能使用了高算法复杂度的命令。还有一种
情况是过度的内存优化，这种情况有些隐蔽，需要我们根据info commandstats统计信息分析出命令不合理开销时间，例如下面的耗时统计：

cmdstat_hset:calls=198757512,usec=27021957243,usec_per_call=135.95

查看这个统计可以发现一个问题，hset命令算法复杂度只有O（1）但平均耗时却达到135微秒，显然不合理，正常情况耗时应该在10微秒以下。这是因为上面的Redis实例为了追求低内存使用量，过度放宽ziplist使用条件（修改了hash-max-ziplist-entries和hash-max-ziplist-value配置）。进程内的
hash对象平均存储着上万个元素，而针对ziplist的操作算法复杂度在O（n）到O（n2）之间。虽然采用ziplist编码后hash结构内存占用会变小，但是操作变得更慢且更消耗CPU。ziplist压缩编码是Redis用来平衡空间和效率的优化手段，不可过度使用。

2.3 持久化阻塞

对于开启了持久化功能的Redis节点，需要排查是否是持久化导致的阻塞。持久化引起主线程阻塞的操作主要有：fork阻塞、AOF刷盘阻塞、HugePage写操作阻塞。

2.3.1fork阻塞

fork操作发生在RDB和AOF重写时，Redis主线程调用fork操作产生共享内存的子进程，由子进程完成持久化文件重写工作。如果fork操作本身耗时过长，必然会导致主线程的阻塞。
可以执行info stats命令获取到latest_fork_usec指标，表示Redis最近一次fork操作耗时，如果耗时很大，比如超过1秒，则需要做出优化调整，如避免使用过大的内存实例和规避fork缓慢的操作系统等。

2.3.2.AOF刷盘阻塞

当我们开启AOF持久化功能时，文件刷盘的方式一般采用每秒一次，后台线程每秒对AOF文件做fsync操作。当硬盘压力过大时，fsync操作需要等待，直到写入完成。如果主线程发现距离上一次的fsync成功超过2秒，为了数据安全性它会阻塞直到后台线程执行fsync操作完成。这种阻塞行为主要是硬盘压力引起，可以查看Redis日志识别出这种情况，当发生这种阻塞行为时，会打印如下日志：

Asynchronous AOF fsync is taking too long (disk is busy). Writing the AOF
buffer without waiting for fsync to complete, this may slow down Redis.

也可以查看info persistence统计中的aof_delayed_fsync指标，每次发生fdatasync阻塞主线程时会累加。
运维提示：硬盘压力可能是Redis进程引起的，也可能是其他进程引起的，可以使用iotop查看具体是哪个进程消耗过多的硬盘资源。

2.3.3.HugePage写操作阻塞

子进程在执行重写期间利用Linux写时复制技术降低内存开销，因此只有写操作时Redis才复制要修改的内存页。对于开启Transparent HugePages的操作系统，每次写命令引起的复制内存页单位由4K变为2MB，放大了512倍，会拖慢写操作的执行时间，导致大量写操作慢查询。例如简单的incr命令也会出现在慢查询中。

3 外在原因

外在原因围绕以下三个方面进行排查：

CPU竞争
内存交换
网络问题

3.1CPU竞争

CPU竞争问题如下：

进程竞争：Redis是典型的CPU密集型应用，不建议和其他多核CPU密集型服务部署在一起。当其他进程过度消耗CPU时，将严重影响Redis吞吐量。可以通过top、sar等命令定位到CPU消耗的时间点和具体进程，这个问题比较容易发现，需要调整服务之间部署结构。
绑定CPU：部署Redis时为了充分利用多核CPU，通常一台机器部署多个实例。常见的一种优化是把Redis进程绑定到CPU上，用于降低CPU频繁上下文切换的开销。这个优化技巧正常情况下没有问题，但是存在例外情况，如下图所示

当Redis父进程创建子进程进行RDB/AOF重写时，如果做了CPU绑定，会与父进程共享使用一个CPU。子进程重写时对单核CPU使用率通常在90%以上，父进程与子进程将产生激烈CPU竞争，极大影响Redis稳定性。因此对于开启了持久化或参与复制的主节点不建议绑定CPU。