从解决Redis访问超时的问题谈起——故事比结果要精彩

标签: redis 访问 问题 | 发表时间:2015-01-17 07:50 | 作者:the5fire
分享到:
出处:http://www.the5fire.com

这周终于解决了Redis访问经常超时的问题,终于可以踏实睡觉了。从上周就开始纠结在这个问题上,可以用寝食难安来形容,感觉这个问题就像个定时炸弹一样,虽然根据手搜的访问量,极少的Timeout Error对用户基本不会造成影响,但是这种问题如果不及时遏制导致Redis整体被拖慢造成的危害是相当严重滴!毕竟在手搜的架构中,Redis是极其重要的一环。

先来讲个故事(说说问题上下文),有兴趣来手搜工作的Python程序员认真听:

前段时间我们新上了个业务,为了满足需求我们对进程级的cache做了些改动,根据业务对cache key进行了拆分,导致的情况是同一份数据会被缓存多份,只因为展示类型不同(可简单理解为不同的展示用的key不同,数据相同)。有经验的同学应该能够想到这么做的结果会是怎么样的——同一份数据会请求两次Redis(因为cache key不同)。(可以看的出来,对于多种展示需求的业务在展示层做cache并不合适) 功能测试没问题,so,上线。晚高峰来了。运维同学和值班同学被报警短信“轰炸”了,大量应用服务器端口访问超时(Nagios监控)。因为那天只有我们的改动上线了,所以可以定位为我们代码的问题。遂,备机上。 次日看日志发现大量的Redis的Timeout Error(timeout=1s),虽然日志中在我们这个系统上线之前就已经存在很多这种日志,显然我们这次改动的上线加剧了这一状况。

从直观的感觉上,我们的功能导致Redis请求增多,因此这时就聚焦在如何较少Redis的请求上。 在分析了一个页面的加载到底会请求多少次Redis之后发现一个很大的问题,因为针对具体业务的设计,一个页面在加载时访问Redis的次数跟页面上展示的内容成正比。因此页面上的内容越多,对Redis的请求会越频繁,因此一次正常的页面访问很可能会产生100次甚至更多的Redis请求。 问题已经很明显了,因为这种设计,必须完全依赖本地缓存,无缓存情况访问页面的速度是不可接受的。

知道问题在哪就好办了,经过不断的思考和尝试,找到一种方案。减少页面上的内容肯定是不行的,那么就只能合并请求了。

说了一大堆,其实问题的本质在于要把之前串行的Redis请求换成并行。另外值得一说的是Redis本身的响应是非常快的,另外还有一些时间消耗在网络上。 串行换成并行的方案可以简单理解为把之前的: GET 1, GET 2 换成: MGET 1 2 这样。改完之后在无缓存的情况下页面加载时间几乎提升了一倍。 OK,既然可行,那就测试,在测试,上线。Yeah!没人被短信轰炸。

你以为故事到这里就结束了,那就太Naive了。Nagios监控只是用来看端口访问是否符合预期的(1s内响应),并不能发现所有的问题。

上线几天之后发现状态码为500的情况增多了,且波动很大。So,继续看日志(有人问,你们不是用Sentry吗?为毛看日志?呃,内个,内个,业务调整...)。 咱们还是来看日志吧,依然是大量的Timeout Error,还是Redis的问题。依据上面的方案我们已经完全减少了Redis请求次数,为何还是慢。

有兴趣的同学可以思考下,为何还是慢?之前的方案会造成哪种影响。

喝口水,继续讲故事:(终于明白知乎上为何经常有人讲故事了,讲故事原来比写正经文章要容易)

为何还是慢呢?之前的改动相当于是把100次请求合并成1次,造成的影响是,虽然减少了网络上的耗时,但是会增加Redis的耗时。假设之前每次请求读10个key(mget),合并成1次请求就变成一次读取1000个key。这块可能是问题原因,那么继续定位吧。 要怎么确定呢?Redis并不熟,但是MySQL有Slowlog,Redis应该也有。于是找到了几个命令:

CONFIG GET slowlog-log-slower-than  (10000us,Redis中的执行单位是微秒,相当于10ms)
CONFIG GET slowlog-max-len  (最多存储128条慢日志,应该是默认的吧?)
SLOWLOG LEN   (128, 靠,存满了)
SLOWLOG GET   (默认去10条)

然后看到了慢日志出现的频率非常高!并且MGET命令中key的数量相当大——1w多(不是上面那个方案导致的),执行耗时在50ms左右。 好了,再次Get到问题所在,解决吧。 然后发现无法从这个日志上去找是哪个项目产生的,因为Redis不记录这个日志产生的client ip。现在回忆知道是哪台服务器发的请求也定位不到。因为这种错误的产生就不是正常业务逻辑代码产生的。

具体调试过程简单概括为:在所有可能产生巨量MGET请求前添加判断,打印log到sentry(没错,我们又上了Sentry服务),主要还是在获取列表的部分(其实最后查到问题的根源完全跟列表没关系),依然没有捕获到任何日志。于是开始到Redis服务器tcpdump所有请求,定位到一台服务器,至少知道了是哪个项目产生的。然后就是运气了,不断的查看正常访问日志。终于发现了问题。太TMD走运了,那一刻都要哭了。这个结果完全不在所有的预料情况之中。

从MGET的key上可以发现所有的新闻都是属于某一个频道,所以我们的预期是这些请求一定是在访问这些新闻所属频道列表页面时产生的。最终发现跟列表页面没半毛钱关系。

看吧,这就是“大型”系统了,充满了不可预测。这样真的不好!

这个问题产生的原因是某个页面中有一部分内容是可以指定获取某频道数据的,但是这部分内容又是存在Redis中的。好吧,之前完全没考虑到会有这种间接的请求。

知道具体问题了,顺藤摸瓜,找到了对应的存在Redis中的内容,奇怪的是这部分内容没有设置要从某个频道获取多少条数据。这个内容的模型大致是这样的:

class Content:
    channel = int()
    data_size = int()

设置了频道,没设置要获取的数量,默认是0。


故事结束,来看代码。

假设我的这个blog系统用的是Redis,那么怎么处理某个频道的分页呢?因为是非关系型数据库。因此在存储数据的时候,我得这样:

import redis

cache = redis.StrictRedis(host='localhost', port=6379)

for post in posts:
    cache.set('blog:post:%s:title' % post.id, post.title)

    cache.zadd('blog:channel:1',time.time(), post.id)

这样存下去如果我要从这个频道(假设id为1)下获取十条数据:

start = 0
count = 10
post_ids = cache.zrange('blog:channel:1', start, start + count - 1)
post_tiltes = cache.mget(map(labda _id: 'blog:post:%s:title' % _id, post_ids))

这样的代码有问题吗?

咋看之下没有问题,因为redis的zset是从0开始计数的,获取10个元素,那就是0到9。那么看下这个描述:

Both start and stop are zero-based indexes, where 0 is the first element, 1 is the next element and so on. They can also be negative numbers indicating offsets from the end of the sorted set, with -1 being the last element of the sorted set, -2 the penultimate element and so on.

大意是,索引从0开始,-1表示最后的一个位置。因此如果你想获取某个频道(id为1)的所有文章id就是这样:

post_ids = cache.zrange('blog:channel:1', 0, -1)

因为-1表示最后一个元素的位置。

再回到上面故事的结尾,那块内容要获取的频道新闻数量为0,而我们的代码和我写的类似,没对这种-1可能性做判断,因此一次就取出来频道下的所有新闻,so,产生了那个结果。


总结时间

在复杂的业务下的复杂的系统结构中,要找到一个隐藏的问题确实不容易,因为写代码的人不断的变化,负责业务的人也在不断变化,最后都不知道这个业务为何存在,是否还在使用,也不知道这段代码是否正常,毕竟每个人还在负责新的业务,不断的添加新的代码。这样的结果就是系统进一步复杂,这样下去的结果就是再经过几年人员的变迁之后,任何一个人想要理解这个系统(这些系统)中的业务逻辑,代码逻辑都将变的十分困难。

代码应该是历史的结果,不应该把历史平铺到代码中,git log才是历史应该存在的地方。 说人话就是:业务的增加不仅仅是增加代码,有时也是要对现有结构进行抽象和重构。

相关 [redis 访问 问题] 推荐:

从解决Redis访问超时的问题谈起——故事比结果要精彩

- - the5fire的技术博客
这周终于解决了Redis访问经常超时的问题,终于可以踏实睡觉了. 从上周就开始纠结在这个问题上,可以用寝食难安来形容,感觉这个问题就像个定时炸弹一样,虽然根据手搜的访问量,极少的Timeout Error对用户基本不会造成影响,但是这种问题如果不及时遏制导致Redis整体被拖慢造成的危害是相当严重滴.

redis 性能问题查找

- - 开源软件 - ITeye博客
          使用redis作为数据库时,系统出现少量超时,通过日志信息发现,超时发生在bgsave时. bgsave命令会fork一个子进程,子进程会将redis数据库信息dump到rdb文件中. 因此不能确定使用bgsave命令时,是fork一个子进程引起超时,还是dump文件时与主进程的sync同步同时写磁盘引起的超时.

redis超时问题分析

- - 搜索技术博客-淘宝
Redis在分布式应用中占据着越来越重要的地位,短短的几万行代码,实现了一个高性能的数据存储服务. 最近dump中心的cm8集群出现过几次redis超时的情况,但是查看redis机器的相关内存都没有发现内存不够,或者内存发生交换的情况,查看redis源码之后,发现在某些情况下redis会出现超时的状况,相关细节如下.

Redis数据“丢失”问题

- - 今天
Redis大部分应用场景是纯缓存服务,请求后端有Primary Storage的组件,如MySQL,HBase;请求Redis的键未命中,会从primary Storage中获取数据返回,同时更新Redis缓存. 如果少量数据丢失,相当于请求”缓冲未命中“; 一般对业务的影响是无感知的. 但现在Redis用作存储的业务场景变多,数据丢失对业务是致命的影响.

Redis集群“倾斜”问题

- - 今天
对分布式存储系统的架构和运维管理,如何保证每个Node的数据存储容量和请求量尽量均衡,是非常重要的. 本文介绍Redis大集群运维过程中,常见导致数据和请求量“倾斜”的场景,及规避措施. Redis数据容量或请求量严重”倾斜”的影响. 以下从运维的角度解释,Redis数十节点的集群,出现数据容量和请求量倾斜情况下,存在的一些痛点:.

Redis实现lock互斥访问资源

- - 数据库 - ITeye博客
Redis是当前很流行的一种开源键值数据库. 目前睿思的后台架构在数据库层采用了Redis和MySQL组合的形式,其中Redis主要用来存储状态信息(比如当前种子的peer)和读写频繁的数据. Redis完全运行在内存之上,无lock设计,速度非常快. 通过实测,在睿思服务器上读写速度达到3万次/s.

Redis响应延迟问题排查

- - searchdatabase
  本文将有助于你找出Redis 响应延迟的问题所在.   文中出现的延迟(latency)均指从客户端发出一条命令到客户端接受到该命令的反馈所用的最长响应时间. Reids通常处理(命令的)时间非常的慢,大概在次微妙范围内,但也有更长的情况出现.   如果你正在经历响应延迟问题,你或许能够根据应用程序的具体情况算出它的延迟响应时间,或者你的延迟问题非常明显,宏观看来,一目了然.

Redis时延问题分析及应对

- - 博客 - 伯乐在线
Redis的事件循环在一个线程中处理,作为一个单线程程序,重要的是要保证事件处理的时延短,这样,事件循环中的后续任务才不会阻塞;. 当redis的数据量达到一定级别后(比如20G),阻塞操作对性能的影响尤为严重;. 下面我们总结下在redis中有哪些耗时的场景及应对方法;. keys、sort等命令.

  导致Redis超时(Timeouts)常见问题

- - 移动开发 - ITeye博客
因实际应用中出现经常 Redis 超时问题,StackExchange.Redis 在 Github 上 Timeouts 一文从多个方面进行分析,并提供相应的解决方案, 为方便日后再次出现该问题时快速查阅,特写下本文作为技术笔记,同时给英文不太好的程序员(媛)提供参考,帮助大家更好的学习redis http://www.maiziedu.com/course/337/.

一个 redis 异常访问引发 oom 的案例分析

- - mindwind
「推断的前提是以事实为依据. 这两天碰到一个线上系统的偶尔出现突然堆内存暴涨,这倒不是个什么疑难杂症, 只是过程中有些思路觉得可以借鉴参考,故总结下并写下来. 内存情况可以看看下面这张监控图. 一天偶尔出现几次,持续时间一般几分钟不等. 当这种情况出现时,我们检查错误日志,发现有下面两几种 OOM 错误.