记一次阿里云日志导致的服务宕机

导航

• 引言
• 火线告警，访问502
• 猜测: I/O频繁惹的祸
• 真相：FullGC突发高频导致程序崩溃
• 移除阿里云日志，稳了
• 结语
• 最后
• 参考

引言

技术人应该具备系统分析，并快速定位问题的能力。

资深技术人需要具备的核心竞争力有哪些？

• 系统分析，并快速定位问题的能力
• 快速地理解需求，转化为流程，架构，并文档输出的能力
• 有一定的产品设计能力，关键时刻可以纠正不良产品设计
• 快速组织人干事的能力

这里的每一项能力都很关键，但是最重要的还是拥有第一项能力。

毕竟，解决问题才是关键。

继上次《记一次加锁导致ECS服务器CPU飙高分析》之后，后面又陆陆续续地遇到并解决了一些新的问题。一直想着记录一下，但是终究因为各种原因没能下笔。

今天给大家分享一下阿里云日志引发的服务宕机问题的解决过程。

火线告警，访问502

项目背景介绍

今年Q2我接管了一个Java项目，接口服务是基于SpringBoot技术框架实现的，部署在阿里云的sae上（SAE是一款 Serverless理念的微服务应用框架）。

配置如下：

• 实例规格: 2Core, 2GiB, 系统盘磁盘空间20GiB
• 运行实例数: 当前2个实例

监控扩容策略:

• 应用扩缩触发值：满足 cpu > 66%
• 应用最小实例数: 2
• 应用最大实例数: 10

该服务是是TOB业务，服务于2000家小微企业。

这里以2023.9.15日监控数据来看，在工作时段(09:30~18:00)，单个实例总TCP连接数平均值约为4K左右。

问题描述

自从进入8月中旬以来，几乎每天都会在报警群里面，收到502告警通知。
这种通常是SAE已经出现自动扩/缩容，导致释放实例出现告警。

每天都会有2~3次报警，可能发生在上午或者下午或者两者都有,让人不厌其烦。

从用户第一的角度，这个老是自动扩容和释放肯定是不友好的。
而B端用户也容易拿这个说事儿，把问题放大。

从技术保障的角度看，这个服务的稳定性是值得商榷的，更不要谈4个9的指标了。

所以，解决服务稳定性是头等大事。

猜测: I/O频繁惹的祸

我连续跟踪了sae的监控日志，并对连续几次扩容时间点的各项指标进行了对比。
初步发现可一个规律: 即每一次触发扩容的cpu飙升，都是伴随着IOPS飙升的。

上图是总体指标，实际上单实例的指标在此之上。

初步断定，程序中可能有功能涉及到磁盘的大量读写，比如文件上传，可能触发了IOPS飙升。

阿里云存储云盘IOPS

IOPS即Input/Output Operations per Second，阿里云服务器存储系统盘IOPS指每秒能处理的I/O个数，IOPS表示块存储处理读写（输出/输入）的能力，单位为次。

部署事务密集型应用，如数据库类应用等典型场景，需要关注IOPS性能，只有挂载到I/O优化的实例时，SSD云盘才能获得期望的IOPS性能。IOPS指标说明：

于是查看阿里云日志，发现还真有个文件上传接口存在性能问题

有图有真相，这更加让我坚信是这个接口导致的问题。

于是连夜做了性能优化，快速上线。

真相：FullGC突发高频导致程序崩溃

道路是曲折的,前途是光明的。

如果仅仅是优化了上面这个接口就能解决，那这个问题也不值得我为此专门写一篇文章了。

实际情况是，第二天，可恶的502问题又出现了。

一筹莫展之际，同组的有个伙伴，这个项目在我接管之前，他是参与时间最长的开发。
他说可能是FullGC频率太高导致。

JVM监控功能用于监控重要的JVM指标，包括堆内存指标、非堆内存指标、直接缓冲区指标、内存映射缓冲区指标、GC（Garbage Collection）累计详情和JVM线程数等。
详细请查看《JVM监控》

于是我们一起看了监控中jvm的指标，下面我整理的9.11当天的FullGC和YoungGC指标。

经过观察，发现FullGC的频率确实偏高，每分钟大概在2~6次。
可以很明确的判断高频的FullGC是服务自动重启的罪魁祸首。

移除阿里云日志，稳了

在断定是FullGC高频这个根本原因之后，我们也做过一种方案，那就是修改JVM调参。

当然，尝试过几次之后，效果不理想，依然每天都出现502。关于JVM调参这个有兴趣的同学可以自己研究。

Log4j

在抛出我的解决方案之前，请允许我介绍一下Log4j。

Log4j是Apache的一个开放源代码项目，通过Log4j可以控制日志的优先级、输出目的地和输出格式。日志级别从高到低为ERROR、WARN、INFO、DEBUG，日志的输出目的地指定了将日志打印到控制台还是文件中，输出格式控制了输出的日志内容格式。

例如某电商公司，希望通过分析用户行为习惯数据（例如用户登录方式、上线的时间点及时长、浏览页面、页面停留时间、平均下单时间、消费水平等）、平台稳定性、系统报错、数据安全性等信息获取平台的最佳运营方案。

阿里云日志服务提供一站式数据采集与分析功能，帮助客户存储并分析日志。

所以，我们的大部分java项目也使用的log4j这个日志库。

• 关于阿里云记录日志可以查看这里：aliyun-log-log4j-appender
• 关于sprigboot,初学者可以参考《Spring Boot 实战纪实(附源码)》

而我的解决方案正好与log4j接入阿里云日志接口相关。

移除阿里云日志

程序中接入阿里云日志，本省就是通过sdk调用接口的过程，即便性能再好的接口，在每分钟3000+次时调用的情况下，也是会暴露出性能的问题。即便阿里云接口抗住了，恐怕我们自己的服务也处理响应不过来。

为啥我会怀疑是阿里云日志的调用问题呢？

恰好我在6月份处理过一个nodeJs项目cpu高的问题。

这个nodeJs项目也是部署在sae上的，是一个群聊的聊天服务器，正常情况下cpu使用率在20%左右，但是在socket连接数大于3k之后，群发消息cpu会急剧飙升。

这个也是我经过差不多一周时间的跟踪，并且在服务器上做了压测复现了的。

而他的最终解决方案就是将程序中阿里云日志服务上报，改成输出到控制台，再由sae再推送给阿里云logstore。

所以，整合了sae 基础监控、JVM指标、阿里云日志网关调用记录，我猜测他们可能本质上属于一类问题。

不管如何，我决定尝试一下。

说干就干，我将Java项目中阿里云日志接口移除，只保留控制台输出。
另外，补充说明一下,只要是输出到控制台日志，sae可以配置logstore,然后转存到指定的阿里云logstore。

令人欣喜的是，第二天，线上没有再报502，连续五天去了，依然稳健。
阿里云日志去除是9.11晚上线的，9.12~9.13两天的jvm监控如下:

从图中可以看到，FullGC的频率始钟控制在1次/min,同时我也统计了单日YongGC的总次数下降了一半。

至此，502的问题总算得以根治。

结语

程序是是有生命的，只要被使用就一定会随着业务的增长，带来新的问题。

解决这些问题的方式很多，一种是升级配置，一种是优化代码。

而很多时候，为了降本增效，我们不得不优化代码。

而这些优化的方式你可以从前辈们的分享中获取，但是很多问题可能是还得自己去摸索。

学习-实践-分享-萃取，周而复始，让知识和经验薪火相传，这也是博客的价值。

希望我的分享能够给你带来帮助，哪怕只是帮你节省了一点点喝咖啡的时间。

最后

这里再啰嗦两句，我们将业务日接入阿里云日志服务，主要是方便后续的日志查询。这个和我们使用ELK搭建日志服务异曲同工。

本文中遇到的问题不是阿里云日志的问题，只是我们的项目接入阿里云日志的方式不太适合当下的场景。我们选择将直接记录改成了异步方式记录，这个有利于降低业务服务器的压力(考虑到我们购买的服务器实例配置太低了,仅有2核2G)。

码字不易，欢迎各位老铁点赞、转发。

参考

• 分析Log4j日志
• 《记一次加锁导致ECS服务器CPU飙高分析》
• 《记一次阿里云日志导致的服务宕机》