线上服务突发性性能骤降的问题排查过程

737 阅读10分钟

1. 问题背景:

周一下午14点,午休起来后,发现我们有一个偏运营社区属性的服务开始有大量的告警,且告警的数量有逐渐增高的趋势,同时服务也有非常高的响应超时,容器实例的状态也在相继的重启中……. 一切的迹象表明,这个问题可能会拖垮服务。

1.png

2.png

2. 处理步骤:

出现线上问题的时候,我们永远应该第一时间想着该如何先恢复,先保证服务的可用性,将故障时间降到最低。但是在当时的现象上,服务正在不停的被接连打死,按照以往的经验,出现这种情况的时候,扩容或者新建全新的服务版本切换流量,很有可能还是会被持续的打死,因为CPU,内存,接口延迟,全部的问题都出现了,很难确定根因,而且主要是延迟的接口几乎是全部的接口,要针对性的去熔断也比较难。

不过好在这个服务并不是我们的核心业务,受影响的功能和用户群也很有限,而且前端也并没有完全不可以用,基于这种情况下,先尝试去先解决故障同时排查解决问题。

  1. 还是依旧老办法先临时新建一个全新的版本以作备份,容器数量相比较旧版本增加一倍,慢慢的将旧版本的流量通过流量灰发的方式慢慢的切换到新版本,用新版本更高的配置和容器数量看看能不能扛住。

3.png

  1. 同时排查服务的监控和异常信息,看看有没有什么线索,发现整个服务的监控信息显示全部都是异常状态,所有的连接池都在等待,接口大量延迟,JVM疯狂full GC

4.png

  1. 分析服务可能是内存出了问题,导致疯狂的GC,接口的请求一直被hold住,arthas dump下日志进行分析,确实是有大量的对象在内存中没有被GC

5.png

  1. 迅速排查这个对象为什么出现,但是比较困难的是涉及到这个对象的方法有好多,再往上去继续溯源调用这些方法的地方就更多,到底是哪里出现的比较难排查。

6.png

  1. 当时有专门通过 arthas 的 各种监控命令去排查这几个方法的调用情况,发现都比较正常,首先请求量不大,很少,其次请求的响应速度和数据量均不是很大,这个就很奇怪….. 按道理,如果这个对象在GC中很多,应该请求的很频繁才对…..

    当时用到了 watch, trace, stack, tt 等等的命令均无有意义的发现(当时情况紧急并没有留下截图)

  2. 在这个时间点,就有点困惑和没有什么头绪了,只能又祭出大招,火焰图(这东西真的是百试百爽,好东西来的)

    终于有了点发现,发现火焰图里总共是3大块,中间绿色的正常的请求,右边的符合预期的大量的GC,但是左边这个是什么鬼……. 为什么这个方法占用这么大量的CPU

    7.png

  3. 迅速排查这个方法,发现确实存在和这个对象相关的很多的调用,迅速判断可能是是这个接口的问题

8.png

  1. 立马去排查监控数据,看看这个接口的情况,发现又和想象中的不一致,这个接口可能出现问题,但是请求量太小了,几乎没有,这么点的请求量就可能打死服务?我有点不敢相信,虽然他的耗时很高。

9.png 9. 这个时候有点无奈,看起来像,但又好像不全是,在排查问题的时候我们同步进行服务恢复和流量迁移,前面说到我们新起了版本(JVM内存配置和容器数量)都是旧版本的2倍,在我们慢慢将流量导入到新的版本后,服务竟然OK了,一点问题都没有非常的平稳和健康。

> 有点欲哭无泪,难道是之前的服务配置不够,新的版本多一倍的配置顶住了……

10. 服务正常了,故障恢复了,继续我们的处理,其实到底为什么好,我们心里压根没底,但是目前看,火焰图,GC日志两个的现象最大的嫌疑点可能还是 上面排查出来的接口,然后找相关的同事确认这个接口是干什么的,同事说是获取埋点上报数据相关的接口,那就好了,不是业务接口,和产品侧沟通先熔断这个接口然后持续观察

10.png

  1. 经过一段时间的持续观察,发现服务整体都是比较平稳,比较正常,心里开始有比较大的信心确定问题应该是这个接口,但是究竟怎么证明,怎么排查,还是有些手头无措。由于当时有更紧急的事情,这个问题在持续观察稳定后,暂时搁置了下。

3. 再次排查:

虽然经过上面的扩容升配以及熔断可能的接口等等操作,服务很长时间都是很稳定的状态,但是心里还是有很大的疑问,虽然看起来服务都是健康OK了,但是实际上并没有查到根因是什么。还是心里过不去,毕竟没找到问题,找了公司比较懂JVM调优的大佬帮忙看看,发现的线索和疑问点也和上面一样,这下就更加深了我对这个接口的怀疑。

这里很感谢大佬分享给我的Jprofiler工具,以前只用这个分析对象和内存,没太关注过传入引用

  1. 用Jprofiler工具分析内存时,查看对象的传入引用,实锤了我的怀疑点,发现每个对象的传入引用都是相同的这个堆栈,也就是上边的接口。

11.png 12.png

  1. 问题确定了,接下来就是怎么验证复现这个问题,毕竟最终还是要用事实说话,仔细分析了下这个数据,发现所有的数据都有一个共同点,他们的followerId都是相同

13.png

这块要说明下这个对象的数据,记录的是一个用户和另外一个用户的关注关系,followerId是关注者,targetUserId是被关注者

这些数据也就是表明,有一段逻辑应该是查某个用户关注的用户列表,如果说,这个用户关注的用户很多,那就是有可能出现查出来数据量很大的情况。

  1. 再来分析下代码:

    override fun statisticsCount(user: UserDto, targetId: String): StatisticsCount {
            val typeRel = listOf(FollowRelRespStatus.TYPE0.type, FollowRelRespStatus.TYPE1.type)
            // 1. 查询 targetId 用户粉丝列表 (问题点1:如果targetId的粉丝数量非常的大,那么fanIds的数量会很多)
            val fanIds = feedUserFollowRelRepository.queryByTargetId(targetId, FeedUserFollowRelStatus.FOLLOW.code)
                .map { it.followerId }
            // 2. 登录userId 都关注了 targetId 用户粉丝列表的那些人
            val meFollowOthersRel =
                feedUserFollowRelRepository.getFollowerRel(user.uid, fanIds, FeedUserFollowRelStatus.ALL.code)
            // 3. 查询 targetId 用户粉丝列表中有多少人,关注了 userId
            val othersFollowMeRel =
                feedUserFollowRelRepository.getTargetUserIdRel(user.uid, fanIds, FeedUserFollowRelStatus.ALL.code)
            val ids = fanIds.filter {
                val type =
                    followService.checkGetStatus(meFollowOthersRel.find { e -> StringUtils.equals(it, e.targetUserId) },
                        othersFollowMeRel.find { e -> StringUtils.equals(it, e.followerId) })
                type in typeRel
            }
            return StatisticsCount(ids.size)
        }
    
    override fun getFollowerRel(followerId: String, targetIds: List<String>, status: Int): List<FeedUserFollowRelDO> {
            if (targetIds.isEmpty()) return emptyList()
            return targetIds.chunked(200).map {
                getBaseMapper().selectList(KtQueryWrapper(FeedUserFollowRelDO::class.java)
                    .eq(FeedUserFollowRelDO::followerId, followerId)
                    .`in`(FeedUserFollowRelDO::targetUserId, targetIds))
            }.flatten()
        }
    
    override fun queryByTargetId(targetUserId: String, status: Int): List<FeedUserFollowRelDO> {
            return getBaseMapper().selectList(
                KtQueryWrapper(FeedUserFollowRelDO::class.java)
                    .eq(FeedUserFollowRelDO::targetUserId, targetUserId)
                    .eq(FeedUserFollowRelDO::status, status)
            )
    }
    
    override fun getTargetUserIdRel(
            targetUserId: String, followerIds: List<String>, status: Int
        ): List<FeedUserFollowRelDO> {
            if (followerIds.isEmpty()) return emptyList()
            return followerIds.chunked(200).map {
                getBaseMapper().selectList(KtQueryWrapper(FeedUserFollowRelDO::class.java)
                    .eq(FeedUserFollowRelDO::targetUserId, targetUserId)
                    .eq(FeedUserFollowRelDO::status, status).`in`(FeedUserFollowRelDO::followerId, followerIds))
            }.flatten()
        }
    

    这端代码的主要逻辑就是计算当前用户A进入到另一个用户B的粉丝列表中后,要计算当前用户A和用户的B的粉丝列表中的所有用户之间的关注关系(是否关注,是否互相关注),有点绕……

    简单说,就像是我在微博进入了一个明星的主页的粉丝列表,要计算我和这个明星的所有粉丝的关注关系。

    理解这个事情,就很容易理解这个问题的发生了,当我(我特别社牛,关注了5W人)要看一个大明星詹姆斯的 粉丝列表(詹姆斯的粉丝量很大,假如是10W)和我的关系时,按照上面逻辑

    1. 先查出来 詹姆斯的 所有粉丝列表 10W+的用户id(很大一批的数据)

    2. 再查出来 我关注了多少詹姆斯的粉丝,用户列表:比如我关注了5W人,这5W人均是詹姆斯的粉丝,那第二步分批去查,每批查询200个,查询500次,查出来的结果就是 5W条记录,故障当时是260w+的记录,整体的占用内存差不多 900MB

    14.png 3. 再反向查 詹姆斯的粉丝有多少关注了我,再将这10W+ 的用户id作为查询参数进行查询,那第二步分批去查,每批查询200个,查询500次。

    1. 执行计算逻辑,且因为第4步还对第二步的结果进行了引用,如果第4步没有执行完,这些对象都属于有引用的对象,无法被GC,内存很容易就会被打爆
  2. 接下来做个测试,我们找一个 ”社牛“ 用户(5W+ 的关注量),再找一个 ”大V“ 明星用户(10W+ 的粉丝数),构造一个这样的接口参数进行测试。

    curl --location 'http://127.0.0.1:8080/feed/v1/follower/statistics/count?targetId=2ec6dasdasdasdd911111a81b34eade9a00b3' \
    --header 'Cookie: x-auth-token = 019a1asdasdada64a0xxx27f7db06015720; x-auth-app = APPCode'
    

    在这里因为线上的用户数比较真实,数据量也比较大,测试环境比较小,我们选择在线上预发环境(没有正常的用户流量,内部预发测试用)测试,同时选择一个较小的容器配置,更容易复现问题,因为预发的流量相比较线上太小了。可以看到发起的请求一直没有响应,容器的内存使用率在接口请求了一段时间后一直也居高不下,过了一会,容器就异常了

    15.png

    16.png

4. 问题总结:

该问题总结下来,主要的原因还是我们对feed或者社区场景下的业务不熟悉(确实第一次做),在业务初始的情况下,并没有考虑到 大V或者社牛的情况,在开发功能的时候比较容易忽略这种用户在业务内的影响,以及特殊的玩法,总的来说还是缺乏这种场景的经验和思考。业务初期的时候,关注数或者粉丝数比较少,基本不会有问题,但是一旦有了大V或者社牛的出现,这种就是巨大的隐患。

这个问题的处理方案是和产品侧沟通下掉这个功能,但是如果不下掉的话,其实我们最好的方式就是要换种方式,因为是上报埋点,这种数据的实时性和准确性其实没有那么高,我们可以用数仓、大数据平台,预计算等等的离线方式预处理,不能在业务和数据库中做这种风险很高的操作。同时也要考虑和产品沟通取舍,从技术可行性和成本方面去讨论这种数据分析的意义和是否有别的分析指标的替代性。

这个问题的排查过程还是常见的内存问题的排查,其实最后的经验就是,善用工具,细心,耐心,一点点的盘,最后总会得到解决的