【微电平台】- 高并发实战经验 - 奇葩问题解决之旅
作者：京东科技 孙亮
微电平台
微电平台是集电销、企业微信等于一体的综合智能 SCRM SAAS 化系统，涵盖多渠道管理、全客户生命周期管理、私域营销运营等主要功能，目前已经有 60+京东各业务线入驻，专注于为业务提供职场外包式的一站式客户管理及一体化私域运营服务。
导读
本文介绍电销系统在遇到【客户名单离线打标】问题时，从排查、反复验证到最终解决问题并额外提升 50%吞吐的过程，适合所有服务端研发同学，提供生产环遇到一些复杂问题时排查思路及解决方案，正确使用京东内部例如 sgm、jmq、jsf 等工具抓到问题根因并彻底解决，用技术为业务发展保驾护航~
下面开始介绍电销系统实际生产环境遇到的离线拒绝营销打标流程吞吐问题。
案例背景
1、概述
每日凌晨 1~8 点会使用 80 台机器为电销系统上亿客户名单进行拒绝营销打标，平均 95 万名单/分钟，拒绝营销 jsf 服务总 tps 约 2 万，tp99 在 100~110ms，若夜间没有完成标记加工操作，会导致白天职场无法正常作业，并且存在客户骚扰隐患、降低职场运营效率的问题，因外部接口依赖数量较多打标程序只能凌晨启动和结束。
2、复杂度
面向业务提供千人千面的配置功能，底层基于规则引擎设计实现，调用链路中包含众多外部接口，例如金融刷单标记、风控标记、人群画像标记、商城风控标记、商城实名标记等，包含的维度多、复杂度较高。
3、问题
2023 年 2 月 24 日早上通过监控发现拒绝营销打标没有执行完成，表现为 jmq 消费端 tp99 过高、进而降低了打标程序吞吐，通过临时扩容、下掉“问题机器****”（上帝视角：其实是程序导致的问题机器）提高吞吐，加速完成拒绝营销打标。
但，为什么会频繁有机器问题？为什么机器有问题会降低 40%吞吐？后续如何避免此类情况？
带着上述问题，下面开启问题根因定位及解决之旅~
抓出幕后黑手
1、为什么几台机器出问题就会导致吞吐急剧下降？
如上图所示，每有一条消息消费报错（在本案例中是打到“问题机器”上），会本地尝试 sleep 并重新消费拉下来的所有消息（本案例中 jmq 的 batchSize=10），即每次报错产生的总耗时至少会增加一千毫秒，一共 80 台机器，jsf 使用默认负载均衡算法，服务请求打到 4 台问题机器的概率是 5%，jmq 一次拉下来 10 条消息，只要有一条消息命中“问题机器”就会极大降低吞吐。
综上所述，少量机器有问题吞吐就会急剧降低的原因是 jsf 随机负载均衡算法下每个实例的命中率相同以及报错后 jmq consumer 重试时默认休眠 1 秒的机制导致。
解决：当然 consumer 不报错是完全可以规避问题，那如果保证不了不报错，可以通过：
1）修改 jmq 的重试次数、重试延迟时间来尽可能的减少影响
2）修改 jsf 负载均衡算法
配置样例：
原理图：
上图中的 consumer 图是从 jsf wiki 里摘取，上面的红字是看 jsf 代码提取的关键信息，总而言之就是：默认的 random 是完全随机算法，最快响应时间是基于服务请求表现进行负载均衡，所以使用最快响应算法可以很大程度上规避此类问题，类似于熔断的作用（本次解决过程中也使用了 jsf 的实例熔断、预热能力，具体看 jsf wiki，在此不过多介绍）。
2、如何判定是实例问题、找出有问题的实例 ip？
通过监控观察，耗时高的现象只存在于 4 台机器上，第一反应确实是以为机器问题，但结合之前（1 月份有过类似现象）的情况，觉得此事必有蹊跷。
下图是第一反应认为是机器问题的日志（对应 sgm 监控这台机器耗时也是连续高），下掉此类机器确实可以临时解决问题：
综上所述，当时间段内耗时高或失败的都是某个 ip，此时可以判定该 ip 对应的实例有问题（例如网络、硬件等），如果是大量 ip 存在类似现象，判定不是机器本身的问题，本案例涉及到的问题不是机器本身问题而是程序导致的现象，继续往下看揭晓答案。
3、是什么导致机器频繁假死、成为故障机器？
通过上述分析可以得知，问题机器报错为 jsf 线程池打满，机器出问题期间 tps 几乎为 0，期间有请求过来就会报 jsf 线程池（非业务线程池）打满，此时有两种可能，一是 jsf 线程池有问题，二是 jsf 线程池的线程一直被占用着，抱着信任中间件的思路，选择可能性二继续排查。
通过行云进行如下操作：
1）dump 内存对象
无明显问题，内存占用也不大，符合监控上的少量 gc 现象，继续排查堆栈
2）jstack 堆栈
从此来看与问题机器表象一致了，基本得出结论：所有 jsf 线程都在 waiting，所以有流量进来就会报 jsf 线程池满错误，并且与机器 cpu、内存都很低现象相符，继续看详细栈信息，抽取两个比较有代表的 jsf 线程。
线程编号 JSF-BZ-22000-92-T-200：
线程编号 JSF-BZ-22000-92-T-199：
推断：线程编号 JSF-BZ-22000-92-T-200 在 UserCrowdHitResult 的 36 行等待，线程编号 JSF-BZ-22000-92-T-199 在 BlacklistBiz 的 337 行等待，查到这，基本能推断出问题原因是线程等待，造成问题的类似代码场景是 1）main 线程让线程池 A 去执行一个任务 X；2）任务 X 中又让同一个线程池去执行另一个任务，当第二步获取不到线程时就会一直等，然后第一步又会一直等第二步执行完成，就是造成线程互相等待的假死现象。
小结：查到这基本可以确认问题，但因代码维护人离职以及程序错综复杂，此时为验证结论先修改业务线程池 A 线程数：50->200（此处是为了验证没有线程等待现象时的吞吐表现），再进行验证，结论是 tps 会有小范围抖动，但不会出现 tps 到 0 或是大幅降低的现象。
单机 tps300~500，流量正常了，即未产生线程等待问题时可以正常提供服务，如图：
印证推断：通过堆栈定位到具体代码，代码逻辑如下：
小结：BlacklistBiz 作为主线程通过线程池 A 执行了 blacklistTempNewService.hit 任务，然后 blacklistTempNewService.hit 中又使用线程池 A 执行了 crowdIdServiceRpc.groupFacadeHit 造成了线程等待、假死现象，与上述推断一致，至此，问题已完成定位。
解决：办法很简单，额外新增一个线程池避免线程池嵌套使用。
4、意外收获，发现一个影响拒绝营销服务性能的问题点
查看堆栈信息时发现存在大量 waiting to lock 的信息：
问题：通过上述堆栈进而排查代码发现一个服务链路中的 3 个方法使用了同一把锁，性能不降低都怪了
解决：通过引入 caffeine 本地缓存替换掉原来使用同步锁维护的手写本地缓存。
5、额外收获，你知道 jsf 线程池满的时候报 RpcException 客户端不会进行重试吗？
这个让我挺意外的，之前看 jsf 代码以及和 jsf 架构师交流得到的信息是：所有 RpcException 都会进行重试，重试的时候通过负载均衡算法重新找 provider 进行调用，但在实际验证过程中发现若服务端报：handlerRequest error msg:[JSF-23003]Biz thread pool of provider has bean exhausted, the server port is 22001，客户端不会发起重试，此结论最终与 jsf 架构师达成一致，所以此类场景想要重试，需要在客户端程序中想办法，实现比较简单，这里不贴样例了。
事件回顾
解决问题后对以前的现象和类似问题做了进一步挖掘，梳理出了如上图的整个链路（问题代码同学早已不在、大可忽略问题人，此处从上帝视角复盘整个事件），通过 2 月 24 号的问题，不但彻底解决了问题，还对影响性能的因素做了优化，最终效果有：
1、解决拒绝营销 jsf 服务线程等待安全隐患、去掉同步锁提升吞吐，tps 从 2 万提升至 3 万的情况下，tp99 从 100ms 降低至 65ms；
2、jmq 重试等待及延迟时间调优，规避重试时吞吐大幅降低：tp99 从 1100ms 降低至 300ms；
3、jsf 负载均衡算法调优，规避机器故障时仍然大量请求打到机器上，效果是服务相对稳定；
最终从 8 点多执行完提前至 5 点前完成，整体时间缩减了 57%，并且即使机器出现“问题”也不会大幅降低整体吞吐，收益比较明显。
优化后的运行图如下：
写在最后
微电平台虽说不在黄金链路，但场景复杂度（业务复杂度、rpa 等机器人用户复杂度）以及流量量级使我们经常面临各种挑战，好在我们都解决了，这里共勉一句话：“在前进的路上总会有各种意想不到的情况，但是，都会拨云见日”。
后面的路，继续努力奔跑，祝每位努力的研发同学都能成长为靠谱的架构师，加油~
版权声明: 本文为 InfoQ 作者【京东科技开发者】的原创文章。
原文链接:【http://xie.infoq.cn/article/ef90cb062ed7e3c18c92e9195】。文章转载请联系作者。
拥抱技术，与开发者携手创造未来！ 2018-11-20 加入
我们将持续为人工智能、大数据、云计算、物联网等相关领域的开发者，提供技术干货、行业技术内容、技术落地实践等文章内容。京东云开发者社区官方网站【https://developer.jdcloud.com/】，欢迎大家来玩
评论