大概从6月底开始,我们的Sentry(错误日志收集、聚合和报警系统 http://getsentry.com )遭遇了性能问题,每分钟只能处理200个事件了,经常有20多万待处理的任务积压在events队列里,延迟超过一小时,我不得不丢弃这些任务,清空队列,以促进时效。重启一下celery worker会有瞬间的改善,但很快就又不行了,似乎worker的性能会衰减。为此,我给celery worker增加了–time-limit参数,使worker不会在执行不下去的时候无限等待,而是超时出错退出,迎接新的任务,情况略有改善。
因为Sentry的结构是前端web-消息队列-后端celery这样的结构,给调试也造成了一些困难。
我先开启了celery worker的DEBUG级别日志,从中搜索包含succeed的行,然后把其中UUID给过滤掉,只保留任务名字和耗时,整理后得到任务和耗时的对应关系,发现save_event这个任务的耗时很有意思,经常是6秒的整倍数。
然后去这个任务里添加时间打点代码,发现在它调用的EventManager.save()函数里,带事务执行的三次数据库插入(调用_save_aggregate、创建EventMapping、保存Event)的耗时,不是零点几秒,就是六秒的整倍数,而完全没有2、3秒、7、8秒这种情况。于是检查的方向就被引导到了数据库方面。折腾了DBA同事几天,删了几个索引和外键约束,也没什么改善。
想到之前为了Sentry的下一个版本v8准备过一套PostgreSQL数据库用于测试,我就拿过来,另外建了一套Sentry 7的部署,在上面运行,没想到性能极其丝滑……事情似乎越来越明了,就是数据库的问题。不过当我停止使用用于测试的128G内存真机PostgreSQL,而自己申请了一个和当前MySQL一样配置的16G机器的时候,发现低配置时pgsql的性能好像还不如MySQL……不过就在我从真实环境往测试环境export/import数据的时候,发现了Sentry在执行import时,如果测试环境共用生产系统的Redis,就会速度极慢,几乎卡死,用strace上去看一下发现慢在Redis操作上,开销在数据库上的时间极少;而如果用专用的一套Redis就速度极快。
于是我的注意力又转向了Redis。尝试FLUSHDB,发现性能立刻恢复了每分钟4000条、峰值8000条的处理能力,但redis的内存碎片率上涨了不少。看了看SLOWLOG,发现有一条几乎占满了整个SLOWLOG排行榜的命令
代码语言:javascript复制ZRANGE b:p 0 -1
手工试了试,这条命令得好几秒种才能返回,一次就能返回数据好几万条。搜了一下源代码,在sentry/buffer/redis.py文件发现了b:p这个key名字。原来,这是把高速更新的计数器的多次更新合并起来,减轻数据库压力的一个组件。但这个组件本身因为把sorted set用到了极限,所以性能不佳。考虑到不能再让碎片率上涨,我只好偶尔手工删除这个key,放弃一些计数器更新操作:放弃更新计数器总比放弃整个任务看起来要好些吧。
去软件原厂求助(https://github.com/getsentry/sentry/issues/3870),作者说我该上供啦,不要自己架服务啦,还是买原厂服务吧……
现在,我更改了worker的配置,把这个任务单独拉出来,用六台worker伺候着,终于基本解决了问题。
顺便说一下我在Redis 2.8.7上遇到的极限值:
sorted set的长度在100万左右就会性能崩溃。如果有依赖这个特性的,请大家注意有可能会引起整体系统的性能雪崩。