发现问题
下午12:20服务器报警CPU过高,
其中两台12:31自动恢复,
一台持续告警至12:51
现场检查发现日志出现大量
1、经分析日志发现12:21开始3台服务器开始出现数据库交互报错日志开始出现:(日志有处理)
#[ap, ...] ERROR 2021-- 12:31:19.181 [*** ***, ***, **] com...SqlTemplate.selectOne:45 -
Error querying database. Cause: java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation
The error occurred while setting parameters
SQL: select * from FM_TABLE where COMPANY = ?
Cause: java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation
由于与数据库交互都报此类错误,导致服务响应异常。
2、及时找dba确认无锁表,外部查询工具查询正常
3、不仅仅FM_TABLE出现超时,其他表也有查询超时
4、后期分析awr无明显异常
5、不是只有一个交易报错,其他交易也有报错
6、开始有部分insert操作报同样错误
7、报错期间运行内存不足,出现多次gc
问题分析
经分析由于服务器压力增加,cpu使用率上升,同时部分调用外服务接口响应时间延长(20+),日志打印增加。导致出现阻塞线程:64个应用业务处理线程、16个日志打印线程。
进而内存不能释放,内存不足频繁GC,最终cpu使用率继续提高。
经测试环境复现使用objbc6:10.2.0时,当程序响应过慢时会报java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation;
替换成较新版本objbc8:12.2.0.1时则不会报错。
测试环境debug模式发现,objbc6:10.2.0、objbc8:12.2.0.1同时存在时会调用objbc6:10.2.0部分方法。
处理方案
近期处理方案:
1、 删除相对较旧驱动,使用新驱动objbc8:12.2.0.1。
2、 优化日志打印,较少不必要日志的打印,减少服务器压力。
3、 调整调用外系统超时时间,减少线程等待,尽快释放资源。
4、 机器配置较好,调整应用启动内存更好使用机器性能。
远期处理建议:
1、 调整部分交易响应方式为异步(比如通知短信等)。
2、 根据需要横向扩展分散压力。