慢接口突增排查（tps暴增）

生产环境突然产生一波RPC超时。

在云服务后台查询报错时间点mysql数据库情况。发现有tps、qps突增。

TPS正常值20左右，突然达到7000+，导致数据库连接池排队，大量请求积压和超时。

event:

error

error.kind:

com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException

message:

Lock wait timeout exceeded; try restarting transaction

stack:

com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)

at com.mysql.jdbc.Util.getInstance(Util.java:408)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:951)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2490)

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)

at com.mysql.jdbc.PreparedStatement.execute$original$3PjVGBhy(PreparedStatement.java:1197)

at com.mysql.jdbc.PreparedStatement.execute$original$3PjVGBhy$accessor$TYFBy4aY(PreparedStatement.java)

at com.mysql.jdbc.PreparedStatement$auxiliary$q8t2Pj2P.call(Unknown Source)

at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)

at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java)

at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:498)

at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:47)

at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)

at sun.reflect.GeneratedMethodAccessor764.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)

at com.sun.proxy.$Proxy324.update(Unknown Source)

at com.baomidou.mybatisplus.core.executor.MybatisReuseExecutor.doUpdate(MybatisReuseExecutor.java:55)

at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)

at com.baomidou.mybatisplus.core.executor.MybatisCachingExecutor.update(MybatisCachingExecutor.java:83)

at sun.reflect.GeneratedMethodAccessor502.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)

 可以看到突增的tps语句是insert。

到云服务控制台，DBA智能运维，全量SQL洞察。查看该时间点的sql语句

 锁定语句后，到代码里找查询代码。

看代码使用的是baomidou  mybatis-plus 里的saveOrUpdateBatch方法。

应该是没有性能问题的。但是峰值tps达到7000+，感觉是并没有生效。

搜索看到这篇文章

https://zhuanlan.zhihu.com/p/433474552

大家需要注意，这个数据库连接 URL 地址中多了一个参数 rewriteBatchedStatements，这是核心。

MySQL JDBC 驱动在默认情况下会无视 executeBatch() 语句，把我们期望批量执行的一组 sql 语句拆散，一条一条地发给 MySQL 数据库，批量插入实际上是单条插入，直接造成较低的性能。将 rewriteBatchedStatements 参数置为 true, 数据库驱动才会帮我们批量执行 SQL。

查看数据连接：

http://Xxx?useUnicode=true&characterEncoding=utf8&serverTimezone=GMT%2B8&allowMultiQueries=true

缺少 rewriteBatchedStatements 参数。

在开发环境测试这个参数：

1万条数据的List调用saveOrUpdateBatch方法，

不带rewriteBatchedStatements=true，耗时347秒。

加上rewriteBatchedStatements=true，耗时2秒。

 

生产环境加上后，同样的调用：

TPS从7000+降低到73。解决。