案例背景
英雄互娱是国内知名游戏研发商和发行商,经常遇到热门线上游戏,在某瞬间出现大量登录请求,需要临时扩容资源的场景。为了让服务更好的应对突增并发请求压力,客户尝试通过把应用服务容器化部署,能通过 HPA(Horizontal Pod Autoscaling)的功能,快速弹性自动扩容应用副本数来提高承载能力。
以下数据均从某已发行游戏的真实环境所得,其应用服务主要基于 Java 技术栈开发。
问题描述
该游戏应用部署在某公有云厂商的托管 K8S 环境中,经过一次更新后,将增加新服节点。以过往经验看,同时跑 6 个相同应用的 Pod,服务的承载能力可以稳定达到每秒 5 万次的 RPS(Request per Second)。但在上线前压力测试后发现,同时跑 6 个 Pod 的 RPS 的承载峰值仅为 2 万出头。增加到 12 个 Pod 时(相同资源配置),RPS 的承载峰值为 2.4 万左右,增长并不明显。进一步增加到 18 个 Pod(相同资源配置),RPS 不再提升,仍停留在 2.4 万左右。这就出现问题了,该服务的承载能力无法随着资源扩容线性增长,将会在高峰期极大影响游戏用户体验。显然瓶颈点会在服务本身,需要配合应用性能监测分析手段来进一步追踪,找出瓶颈点并执行优化。
绿线为 RPS,峰值为 2.4 万
黄线为响应时间(Response Time),峰值约为 1000ms
使用观测云定位问题的过程
观测云是系统全链路数据可观测平台,非常适合高效定位上述问题根因。观测云应用性能监测支持使用 OpenTracing 协议的采集器,实现对分布式架构的应用进行端到端的链路分析,并能与基础设施、日志、用户访问监测进行关联分析,快速感知故障表象和定位故障根因,提高用户体验。
- 通过链路观测快速定位问题方向
1. 在容器服务环境中部署观测云的数据采集器 - DataKit,接入应用链路和日志数据。
2. 服务在 21:00 到 22:00 点间进行压测,压测开始后,观测云应用性能监测的服务概览页面立即显示出系统实时运行状态,通过对 Pxx 的响应时间做排序,快速找到了响应时间较长的服务。如下图所示:
3. 点击该服务做进一步下钻,可以看到更详细的调用相关信息。如下图所示,发现「POST /xxx/v1/login/checklgn.lg」的响应时间较长,并且随着压力的增大,平均响应时间会逐渐增加。定位到该条服务链路需要做进一步的排查。
4. 点击该服务调用,进一步下钻去探查资源详情,我们注意到该服务执行会非常频繁的去调用 Redis(56 次),如下图所示。如果并发量增大,频繁调用该服务的时候,很可能会造成 Redis 上的巨大压力。
5. 从火焰图中,我们可以看到有些 Redis 调用之间存在可疑的延迟(注意红圈部分)。虽然,Redis 本身执行的时间非常快,但因为调用间的延迟拖慢了整体性能。
随着对系统的压力增大,该现象会更加明显。下图是压测高峰期产生的火焰图。从图中可以看到,两个 Redis 间的调用延迟超过 2s。
所以,初步判断瓶颈点在 Redis 上,原因很可能是 Redis 端的压力较大,无法即时响应前端调用所需的相关资源(例如:获取连接),出现了等待,从而导致在压测中整体的 RPS 上不去。此时,压测才刚开始不到 5 分钟,观测云快速定位性能瓶颈点的能力让现场工程师着实震惊。
6. 接下来就要进一步分析是 Redis 配置的问题,还是访问代码的问题了。首先开启 Redis 监测仪表板,从 Redis 的指标监控来看,在压测高峰期,出现 CPU 被打满的情况。尝试对 Redis 相关的参数做了优化调整,比如,增加连接池中连接数的数量,长链接代替短连接等的配置后,6 个 Pod 配置下压测结果 RPS 峰值可提升到 3 万左右,但再增加 Pod 数量后,RPS 峰值几乎没有变化。根因范围进一步缩小了,极有可能是访问代码的问题。但这时候现场工程师稍有犯难,此时已经是深更半夜了,这时候不可能再拉开发进来逐个模块检查代码,但明明就快揭开问题根因了,要拖到明天再继续又实在心有不甘。
这时候可以用观测云的 Profiling 能力了。
- 通过 Profiling 功能发现代码层问题
观测云 Profiling 功能支持查看应用程序运行过程中 CPU、内存和 I/O 的使用情况,通过火焰图实时展示每一个方法、类和线程的调用关系和执行效率,帮助优化代码性能。
现场再继续以下操作配置:
1. 在观测云中开启 Profiling 的采集功能。
2. Profiling 默认会1分钟左右上传一次统计数据。我们对压测开始时的数据和运行一段时间后的数据做比较,主要关注在「Lock Wait Time」和 「Socket I/O Read Time」的指标上。如下图所示:
1) 压测开始时的 Profiling 数据
2) 压测一段时间后的 Profiling 数据
压测中是逐步增加 RPS 的量,从上图的对比中,可以清楚的看到压测过程中「Lock Wait Time」 和 「Socket I/O Read Time」的值会变得非常大。这里就可能存在瓶颈点。需要进一步下钻去看更详细的信息。
3. 从 Redis 监控指标发现有大量的 Read 操作。所以,进一步看「Socket I/O Read Time」相关的详细信息。如下图所示:
调用顺序按列从上往下,方块越长代表耗时占比越大。如上图红色标记的 3 个方块基本是最耗时的调用。在右侧,也可以通过不同的维度(类,方法,包等)进行数据查看。选择其中 ActionHandler 继续往下一级下取信息。
4. 在 ActionHandler 的详细信息中,能看到客户的代码中通过不同的实现方法在频繁调用 Redis 来完成相关的操作。如下图所示:
其中,以 setCacheModel 和 addCount 方法占用的时间最多。
5. 用同样的方法,发现其他的类方法中例如 Invocation.invoke() 等都存在类似频繁调用 Redis 的情况。这种情况会导致一个服务调用会产生大量的服务调用。当并发量大的时候,Redis 会成为热点,压力较大。
此时已是第二天凌晨,但终于找到了问题根因,的确因为代码内对 Redis 过于频繁的冗余调用所导致,甚至能清晰的定位到有问题的方法名,只待给开发提 ISSUE 即可。
最终成效
代码优化后,效果远超预期!
第二天,开发同学在观测云面板上,回溯到昨晚压测过程的时间段,看到了当时应用状态仪表板和 Profiling 仪表板数据,快速理解了问题上下文,当天就完成了相关代码部分的优化并提了测试发版。
在当晚 21 点开始的新一轮的压测中,仍使用 6 个 Pod,RPS 跑到了超过 8 万峰值,相比第一次压测的 2 万 RPS 结果,性能足足提升到 4 倍,同时响应时间仍能控制在 800ms 以下,结果远超预期。