从一个实际问题出发讲讲排错思路

王大爷 2022年05月07日 415次浏览

排查经历

问题现状

问题现状是,保存作品,发放奖品,偶现500错误,请求超时,查看日志,错误日志如下。

查看日志

org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:287) ~[spring-jdbc-4.3.29.RELEASE.jar!/:4.3.29.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:377) ~[spring-tx-4.3.29.RELEASE.jar!/:4.3.29.RELEASE]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:464) ~[spring-tx-

这类问题,其实归根就是猜,带着思路和线索去猜,这类问题一般可能由多种原因联合引发,有同学说看源码,看源码可以协助,但是不能对它报太多期望,因为通常很多人只能胜任一道俩门语言,如果出现一个问题,跨多端引发,这时候就无法通过阅读源码去发现。

由于它是偶现,通常很多次之后保存作品,发放奖品,触发之后偶现几次,这俩个操作的共同特性是用到的事务比较多,事务比较大,可能一次请求耗费了多个事务。一个事务对应一个连接。

第一个猜测

由于我们mps的连接池配置最大为50,如果定时任务中的出现大事务,定时任务的执行频次较高,比如一个定时任务执行需要耗费2分钟,但是该定时任务5秒触发一次,每次开启一个大事务,这种情况,单纯的定时任务就会把连接池耗光,影响其他请求。

image.png

经过检查代码,发现代码里有定时任务加事务的情况。修复了之后,仍然会有这种情况,但是情况缓解了不少,经过阅读源码,hikariPool连接池,即便没有使用场景也会有连接池保持功能,会隔一段时间释放未被使用连接,再重新申请一批连接。

第二个猜测

此时还没有找到核心问题,还是时不时的会出现CannotCreateTransactionException问题,这问题,应该是从mysql那一层抛出来的,我想到了我们的一个线上问题,数据库被打爆的情况,其他应用也受影响了,那会不会是mysql被其他应用搞满载了,然后影响到了我们当前微服务,

证实了我的猜测

image.png
mysql一直处于满载的状态,检查具体线程

image.png

page_cleaner_thread 线程导致的,这个线程是mysql专门用来刷脏页的线程,这个线程负载过高,一般情况是,update,insert,select交互频次过高,https://www.modb.pro/db/176619

一个数据刚被写入,立马就需要被读取。

这时候逐个排斥连接该mysql的java应用,排查到某个项目时,jprofiler以下异常

ygc的频次很高,然后定时任务update频次过高。

image.png

image.png

update每秒操作数据接近1000次 ,触发入口定位,

image.png

跟业务那边交流是,代码里面脏数据导致陷入了死循环可能是 。

image.png

业务开发解决配合问题了之后,查看一切性能指标恢复正常。

最终,定时任务 每秒 update 几十条数据,mysql cpu负载恢复正常。

image.png

image.png

image.png

后面开发环境没出现过,CannotCreateTransactionException,这类问题。

说点个人心得

掌握各种工具,并知道工具的边界。

  • arthas 是一个查看实时日志的工具集,也可以窥探内存属性,代码定位是强项,性能问题排查是它的短板。
  • Jprofier是一个诊断器,可以可视化实时的展示项目所有指标,但是代码定位是它的短板,不够灵活。
  • gceasy gc日志在线分析。
  • Percona Toolkit,是一个mysql 分析的工具包,慢查询日志分析,以及mysql健康状态检测。
  • redis AOF文件分析工具hiredis AOF分析
  • 适当的代码阅读能力,比如有时候发现连接频繁关闭打开,这时候需要阅读源码了解框架的机制,判断是否是框架机制导致,而不是异常情况。(可以配合arthas命令,查看运行时属性值)
  • 掌握普通查看命令行组合使用

比如,针对某个线程,代码的定位可以如下操作。

1.确定哪个进程PID的cpu异常高

top或htop,找到cpu异常高的进程PID

2、确定该进程下的哪个线程PID的cpu异常高

top -Hp 进程PID,找到cpu异常高的线程PID

3、打印该线程十六进制地址

printf "%x\n" 线程PID,获取到十六进制地址

4、确定是在执行程序的哪段代码

jstack 进程PID | grep -A30 十六进制地址

在掌握了这些工具后,在排查问题的时候,思路更广阔一些,不至于只会百度。找错就是一个大胆假设,小心求证的过程,你掌握的这些工具就作为你求证的工具。

易现问题

基本性能问题,比如慢查询,gc异常。基本使用arthas就能能解决。

这种问题一般,大概心理有数,哪个接口,哪段代码,基本的排除法就能够解决这种问题。使用arthas的trace,和 expian 基本可以大致定位问题。

这里我有几点心得,通常是异常频次比较高的几个类型

  • for循环里不要做io操作,包括本地io,远程io。有的同学喜欢在for循环里操作redis,或者本地磁盘,这种很容易引起性能问题。一个接口一次for循环,100次来说,每次远程io即便只花费2毫秒,这个for循环跑完,也至少200ms,还不算其他逻辑。

  • 慢查询问题,通常是没有好好利用上索引导致,能使用联合索引的尽量使用联合索引,因为联合索引的唯一性是高于单个索引的。索引的效率通常是唯一性越高的索引查询效率越高。

  • 大数据量查询问题,这点尤其在定时任务上明显,有的人,认为定时任务不需要考虑性能,在写sql脚本的时候马虎,比如不做分页,一次返回上万,几十万条数据,这样会导致俩个问题。1.mysql的负载受不了,会通过mysql级联影响到其他应用。2.java项目oom。

这些问题,通常使用arthas和pt-query-digest工具包,基本就可以一目了然,比较容易定位。

非易现问题

  • 有的问题不是一下子能定位到的,这类问题通常,由一个核心问题,级联引发很多种不同的现状,不好定位排查,它可能由多方引起,这种情况就需要借助上面介绍的工具,慢慢试探,找蛛丝马迹,一点点抽丝剥茧,最终解决问题。

  • 看日志,不要看一方的,要多方查看比对确保排查大方向是正确的,比如,redis连不上,到底是服务器网络的问题,还是redis自身的问题。

  • 排查问题有节点思路,理清大概流程,把大流程分为多段,大概定位到问题具体在哪个段上发生,再重点关注该段上的动作。