记一次阿里云日志导致的服务宕机
导航
- 引言
- 火线告警，访问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指标说明：
指标 | 描述 | 数据访问方式 |
总IOPS | 每秒执行的I/O操作总次数 | 对硬盘存储位置的不连续访问和连续访问 |
随机读IOPS | 每秒执行的随机读I/O操作的平均次数 | 对硬盘存储位置的不连续访问 |
随机写IOPS | 每秒执行的随机写I/O操作的平均次数 | |
顺序读IOPS | 每秒执行的顺序读I/O操作的平均次数 | 对硬盘存储位置的连续访问 |
顺序写IOPS | 每秒执行的顺序写I/O操作的平均次数 |
于是查看阿里云日志，发现还真有个文件上传接口存在性能问题
有图有真相，这更加让我坚信是这个接口导致的问题。
于是连夜做了性能优化，快速上线。
真相：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)。
码字不易，欢迎各位老铁点赞、转发。
