问题爆出
企微群告警爆了,立即去看ELK报错日志,报错日志非常莫名其妙:java.lang.ArrayIndexOutOfBoundsException: 16
原因分析
事后发现共有18257次报错日志,时间跨度 19:09:24.331 – 19:19:20.332,如下截图所示:
这个时间点正好是让DBA操作执行DDL语句,表加字段:ALTER TABLE channel_advertiser_id ADD COLUMN stop_time timestamp default NULL COMMENT '账户关停时间' after status;
执行时间为19点9分21秒,执行耗时不过3秒,19点9分24秒就执行完成。
看到数据越界,思维会习惯性以为查询出重复的数据。于是查询表的总记录数为3235条,没有重复的数据。
可知,表的数据量非常少,但是是一个非常核心的业务主表。0.17s就有194次报错日志:
ELK最早一条报错日志:
19:09:24.331 [SchedulerFactory_Worker-17] ERROR c.p.c.b.j.t.PutAdCreativeMaterialJob - PutAdCreativeMaterialJob error:org.springframework.dao.TransientDataAccessResourceException:
### Error querying database. Cause: java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
### The error may exist in URL [jar:file:/opt/app/octopus-backend.jar!/BOOT-INF/classes!/mybatisKraken/ChannelAdvertiserIdMapper.xml]
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select * from channel_advertiser_id where isactive = 1 and advertiser_id = ?
### Cause: java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
; SQL []; java.lang.ArrayIndexOutOfBoundsException: 16; nested exception is java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: 16
至此还是莫名其妙,毫无头绪。
不过大体上的思路还是有的,无非是2个:
- 找日志
谛听(内部应用,类似于开源的SkyWalking)报错日志:
java.lang.ArrayIndexOutOfBoundsException: 16<MSG>16
java.sql.SQLException
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73)
at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:441)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute$original$HSVORnno(ClientPreparedStatement.java:370)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute$original$HSVORnno$accessor$gSEmEInd(ClientPreparedStatement.java)
at com.mysql.cj.jdbc.ClientPreparedStatement$auxiliary$ksqk50q8.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java)
at com.mysql.cj.jdbc.ServerPreparedStatement.execute$accessor$mLgNCD2S(ServerPreparedStatement.java)
at com.mysql.cj.jdbc.ServerPreparedStatement$auxiliary$3DrEHQTx.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
at com.mysql.cj.jdbc.ServerPreparedStatement.execute(ServerPreparedStatement.java)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:108)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy437.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
at sun.reflect.GeneratedMethodAccessor169.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy138.selectOne(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy152.selectAdvertiserIdById(Unknown Source)
at sun.reflect.GeneratedMethodAccessor168.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
at org.springframework.aop.framework.ReflectiveMethodInvocation
同时也找到类似(不完全一样)的几个ArrayIndexOutOfBoundsException报错记录帖子,见参考。
看源码com.mysql.cj.jdbc.ServerPreparedStatement
(有删减),简单分析:
protected <M extends Message> com.mysql.cj.jdbc.result.ResultSetInternalMethods executeInternal(int maxRowsToRetrieve, M sendPacket,
boolean createStreamingResultSet, boolean queryIsSelectOnly, ColumnDefinition metadata, boolean isBatch) throws SQLException {
synchronized (checkClosed().getConnectionMutex()) {
((PreparedQuery<?>) this.query).getQueryBindings()
.setNumberOfExecutions(((PreparedQuery<?>) this.query).getQueryBindings().getNumberOfExecutions() + 1);
// We defer to server-side execution
try {
return serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata);
} catch (Exception ex) {
if (this.session.getPropertySet().getBooleanProperty(PropertyKey.enablePacketDebug).getValue()) {
this.session.dumpPacketRingBuffer();
}
// 报错441行
SQLException sqlEx = SQLError.createSQLException(ex.toString(), MysqlErrorNumbers.SQL_STATE_GENERAL_ERROR, ex, this.exceptionInterceptor);
if (this.dumpQueriesOnException.getValue()) {
String extractedSql = toString();
StringBuilder messageBuf = new StringBuilder(extractedSql.length() + 32);
messageBuf.append("\n\nQuery being executed when exception was thrown:\n");
messageBuf.append(extractedSql);
messageBuf.append("\n\n");
sqlEx = appendMessageToException(sqlEx, messageBuf.toString(), this.exceptionInterceptor);
}
throw sqlEx;
}
}
}
执行return serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata);
时抛错,ServerPreparedStatement.serverExecute
方法
protected ResultSetInternalMethods serverExecute(int maxRowsToRetrieve, boolean createStreamingResultSet, ColumnDefinition metadata) throws SQLException {
synchronized (checkClosed().getConnectionMutex()) {
this.results = ((ServerPreparedQuery) this.query).serverExecute(maxRowsToRetrieve, createStreamingResultSet, metadata, this.resultSetFactory);
return this.results;
}
}
ServerPreparedQuery.serverExecute
方法
public <T extends Resultset> T serverExecute(int maxRowsToRetrieve, boolean createStreamingResultSet, ColumnDefinition metadata,
ProtocolEntityFactory<T, NativePacketPayload> resultSetFactory) {
if (this.session.shouldIntercept()) {
T interceptedResults = this.session.invokeQueryInterceptorsPre(() -> {
return getOriginalSql();
}, this, true);
if (interceptedResults != null) {
return interceptedResults;
}
}
String queryAsString = this.profileSQL || this.logSlowQueries || this.gatherPerfMetrics ? asSql(true) : "";
NativePacketPayload packet = prepareExecutePacket();
NativePacketPayload resPacket = sendExecutePacket(packet, queryAsString);
T rs = readExecuteResult(resPacket, maxRowsToRetrieve, createStreamingResultSet, metadata, resultSetFactory, queryAsString);
return rs;
}
执行查询时,需要使用到session。而加字段后,session信息发生变更?
另外从源码搜索反向分析,找到ArrayIndexOutOfBoundsException可能出现在NativeServerSession类里面:
能力有限,只能分析到这个地步。
另外,报错的数据越界的数字也是有讲究的,看一下表的定义(注释省去,字段名字母有删减):
create table channel_advertiser_id (
id int auto_increment primary key,
adv_id varchar(100) null,
aer_name varchar(100) null comment '',
adve_name varchar(100) null comment '',
cha_id text null comment '',
cor_id int null comment '',
use_id int null comment '',
isactive tinyint(1) not null,
insert_time timestamp default CURRENT_TIMESTAMP not null,
update_time timestamp default CURRENT_TIMESTAMP not null on update CURRENT_TIMESTAMP,
updateby varchar(100) null comment '',
isot int(5) default 2 not null comment '',
status int(5) default 1 not null comment '',
stop_time timestamp null comment '账户关停时间',
advd_id varchar(50) null comment '',
is_ew tinyint(1) default 0 null comment '',
cony varchar(100) null
) charset = utf8;
发布前16个字段,发布后17个字段。
注:mysql-connector-java版本为8.0.22,
反思
假使按照规范,DBA是21点(整点)执行DDL语句。虽然DBA不一定会卡整点执行。但是生产上很多跑批任务大多数都是整点或者半点执行的。19点10分有1.8w次报错。那21点多执行,虽然不是业务使用高峰期,那还是会有这个问题???
参考
版权声明:本文内容由互联网用户自发贡献,该文观点仅代表作者本人。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如发现本站有涉嫌侵权/违法违规的内容, 请发送邮件至 举报,一经查实,本站将立刻删除。
文章由极客之音整理,本文链接:https://www.bmabk.com/index.php/post/142116.html