前情概要
4月份某天下午刚上班，春困之际，整个人还不是非常的清醒，结果钉钉开始收到告警，线上一台服务在非常频繁fullGC，一下子，整个人清醒多了，这个不是一个简单的告警，对服务的影响非常大。确实如此，没过几分钟，下游服务开始调用超时告警
我们公司内部的APM工具是pinpoint，可以看到服务超时13:50～14:03这段时间内服务响应时间有很多超过了5000ms
找到出问题的那台"那台实例
红线表示fullGC，基本上这个实例处于不可用的状态，分发到这个实例的请求基本上也就是超时，其他实例此时正常，我们服务总共部署了五个实例，只有这个实例出了问题
快速恢复
- 下线出问题的实例，记得这里先dump堆文件
问题分析
原因分析
根据以上现象，猜测应该是某个不常用的请求或者某种特殊的场景导致内存加载了大量数据，正好这个请求是由出问题的这个实例来处理的。
因为服务了过了一会就恢复了正常，服务日志里也找不到任何的有用的信息，分析陷入了瓶颈，但这个问题只要出现一次，就会导致服务基本上不可用，所以还是要找到根本的原因，彻底的根治这个问题，避免后续产生更大的影响。
我们的服务加载数据的途径有限，要么是数据库查询，要么是外部接口返回，根据dump文件其实可以看出来对象其实大部分都是我们内部的实体对象(这里忘记截图了)，所以应该是数据库查询返回了大批量数据。
解决思路
JVM参数调整: 调整JVM参数，尽可能避免出现该问题
代码逻辑调整: 找到问题代码并修复
JVM参数调整
整个调整的思路是尽可能最小化"短暂对象"移动到老年代的数量，避免老年代快速膨胀，触发majorGC或者fullGC，进而导致服务STW，影响业务，但是这个调整也无法避免代码导致的极端情况
-Xmx5g
-Xms5g
-XX:MaxMetaspaceSize=512M
-XX:MaxTenuringThreshold=15
-XX:MetaspaceSize=512M
-XX:NewSize=2560M
-XX:MaxNewSize=2560M
-XX:SurvivorRatio=8
-XX:+UseConcMarkSweepGC
-XX:+PrintGCApplicationStoppedTime
-XX:+UseCMSCompactAtFullCollection
-XX:CMSInitiatingOccupancyFraction=85
-Xloggc:/opt/zcy/modules/agreement-center/gc.log
-XX:CMSFullGCsBeforeCompaction=2
-XX:+CMSScavengeBeforeRemark
-XX:+UseCMSInitiatingOccupancyOnly
- 调整新生代的大小:-xx:NewSize=2560M,-xx:MaxNewSize=2560M, 我们堆大小为5g，调整新生代大小到2560M，为整个堆大小的一半，尽可能<typo id="typo-1301" data-origin="的" ignoretag="true">的</typo>让更多的类可以放到新生代
- 调整对象晋升到老年代的年龄阈值: -XX:MaxTenuringThreshold=15, CMS中该值默认为6，调整到15，让对象尽可能保留在新生代，在新生代完成回收
- 调整survivor区与Eden区的比例: -xx:SurvivorRatio=8, 换算一下，Eden区大小等于2560M*0.8 = 2048M
代码逻辑调整
这里的解决思路是，限制代码大批量数据查询，找出代码里大批量查询数据库的坏代码并修复
- 方案一：通过mybatis插件，全局查询语句加上limit，限制最大的返回数据，但是我们的业务中，经常有关联数据好几万条，这里其实数据结构设计是不合理，这个limit大于好几万也就失去了意义，因为有些表单行记录比较大，几万条记录也有几百兆，请求量大的时候，也会出现这个问题，而且也不能发现出问题的代码，项目代码太多了，看代码找问题只能看缘分，不靠谱
- 方案二：也是通过mybatis插件，统计每次查询结果的数量，大于某个阈值打印告警日志，实时监控该日志，根据日志找到整个链路，进而找到出问题的代码
我这里采用了第二种方案，插件代码如下:
@Intercepts(@Signature(type = ResultSetHandler.class, method = "handleResultSets", args = {Statement.class}))
@Slf4j
public class QueryDataSizeInterceptor implements Interceptor {
/**
* 查询条数限制，超过打印warn日志
*/
private Integer querySizeLimit;
/**
* 是否开启
*/
private Boolean isOpen;
public QueryDataSizeInterceptor(Integer querySizeLimit, Boolean isOpen) {
this.querySizeLimit = querySizeLimit;
this.isOpen =isOpen;
}
@Override
public Object intercept(Invocation invocation) throws Throwable {
try {
if (isOpen) {
processIntercept(invocation.getArgs());
}
} catch (Throwable throwable) {
log.warn("QueryDataSizeInterceptor.failed,cause:{}", Throwables.getStackTraceAsString(throwable));
}
return invocation.proceed();
}
private void processIntercept(final Object[] queryArgs) {
Statement statement = (Statement) queryArgs[0];
try {
HikariProxyResultSet resultSet = (HikariProxyResultSet) statement.getResultSet();
MetaObject metaObject1 = SystemMetaObject.forObject(resultSet);
RowDataStatic rs = (RowDataStatic) metaObject1.getValue("delegate.rowData");
if (Objects.nonNull(rs) && !rs.wasEmpty() && rs.size() >= querySizeLimit) {
MetaObject metaObject2 = SystemMetaObject.forObject(statement);
String sql = (String) metaObject2.getValue("delegate.originalSql");
log.warn("current.query.size.is.too.large,size:{},sql:{}",rs.size(), sql);
}
} catch (Throwable throwable) {
log.warn("QueryDataSizeInterceptor.failed,cause:{}", Throwables.getStackTraceAsString(throwable));
}
}
@Override
public Object plugin(Object target) {
return Plugin.wrap(target, this);
}
@Override
public void setProperties(Properties properties) {
}
}
大部分代码都是mybatis的插件模版代码，核心代码很简单
private void processIntercept(final Object[] queryArgs) {
Statement statement = (Statement) queryArgs[0];
try {
HikariProxyResultSet resultSet = (HikariProxyResultSet) statement.getResultSet();
MetaObject metaObject1 = SystemMetaObject.forObject(resultSet);
RowDataStatic rs = (RowDataStatic) metaObject1.getValue("delegate.rowData");
// 某次查询超过配置的条数时，打印warn日志
if (Objects.nonNull(rs) && !rs.wasEmpty() && rs.size() >= querySizeLimit) {
MetaObject metaObject2 = SystemMetaObject.forObject(statement);
String sql = (String) metaObject2.getValue("delegate.originalSql");
log.warn("current.query.size.is.too.large,size:{},sql:{}",rs.size(), sql);
}
} catch (Throwable throwable) {
log.warn("QueryDataSizeInterceptor.failed,cause:{}", Throwables.getStackTraceAsString(throwable));
}
}
代码逻辑: 某次查询超过配置的条数时，打印warn日志。并在日志平台配置对应日志的钉钉告警
再次出现
有了日志，通过traceId马上就能找到对应代码了，可以看到这里从数据库查询30多万数据到内存，触发fullgc也是正常的
Long total = protocolQualificationManager.count(criteria);
if (total == 0) {
return Response.ok(new Paging<>(0L, Collections.EMPTY_LIST));
}
//List<AgProtocolQualification> result = agProtocolQualificationDao.paging(criteria);
List<AgProtocolQualification> result = protocolQualificationManager.paging(criteria);
Set<Long> protocolIds = FluentIterable.from(result).transform(k -> k.getProtocolId()).toSet();
// 这个查询出了问题
List<AgProtocol> protocols = agProtocolDao.queryByIds(Lists.newArrayList(protocolIds));
代码看起来没啥问题呀，<typo id="typo-5521" data-origin="在" ignoretag="true">在</typo>看对应的查询的mapper
<select id="queryByIds" parameterType="java.util.List" resultMap="defaultResultMap">
SELECT
<include refid="allColumns"/>
FROM
ag_protocol
<where>
<if test="ids != null and ids.size != 0" >
and id in
<foreach collection="ids" open="(" close=")" separator="," item="id">
#{id}
</foreach>
</if>
<!--后面加的代码 防止查询全表 -->
<if test="ids == null or ids.size == 0" >
and false
</if>
<include refid="not_deleted"/>
</where>
</select>
- 这里没有做限制，当ids为null，全表查询not_deleted的数据，30多万条记录全部返回
坑点和教训
- 动态sql 如果所有条件都未匹配，不能直接查询全表，应该返回为空，要在代码里或者mapper sql中加以限制
- 优化业务数据结构，在代码里加上limit限制
- 数据库层面也要做限制，如果这里是大批量的删除，可能业务影响会更大
作者：政采云技术团队
链接：https://juejin.cn/post/7023164662187294733
