简单做一下线上问题排查的记录。使用的Mysql引擎是 InnoDB 5.7。
排查log
通过排查应用日志（只有其中一台机器），可以马上定位到问题是数据库连接池满了。具体日志如下:
2018-05-10 10:42:16.824 WARN 5 [xec-3303] SqlExceptionHelper SQL Error: 0, SQLState: null
2018-05-10 10:42:16.824 ERROR 5 [xec-3303] SqlExceptionHelper wait millis 5000, active 80, maxActive 80
2018-05-10 10:42:16.864 ERROR 5 [xec-3303] StorageOutputService Error Storage output create，createDTO:StorageOutputCreateDTO{...}.
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:431)排查db
通过查看DB的TPS以及连接池占用情况发现，DB的连接数并没有被占满，其他服务可以正常获取DB连接并正常运行。于是在排查具体问题之前，做的第一件事就是调整负载均衡，关闭该服务的流量，如果线上QPS以及其他机器负载不大的话，最好保留问题现场。同时对日志进行进核对（因为当时该微服务没有重要级写数据场景，所以没有再做数据核对，否则要进行数据校准）。
进一步排查。当时首先想到的是是否会存在死锁，导致大多数线程都对锁资源进行竞争。
查看innodb status（以下为展示用的测试环境数据）:
$show engine innodb status
.... Per second averages calculated from the last 29 seconds -----------------
BACKGROUND THREAD -----------------
srv_master_thread loops: 387668 srv_active, 0 srv_shutdown, 21764038 srv_idle srv_master_thread log flush and writes: 22151706 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 2011323 OS WAIT ARRAY INFO: signal count 2007205 RW-shared spins 0, rounds 1233550, OS waits 539444 RW-excl spins 0, rounds 4440731, OS waits 230776 RW-sx spins 931, rounds 92672, OS waits 785 Spin rounds per wait: 1233550.00 RW-shared, 4440731.00 RW-excl, 99.54 RW-sx ............ ------------
TRANSACTIONS ------------
Trx id counter 2409202
Purge done for trx's n:o < 2409201 undo n:o < 0 state: running but idle
History list length 948
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421319541227184, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421319541211680, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421319541245424, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
...... 通过查看innodb status中的TRANSACTION以及Lock,并没有查到死锁信息。
再查看表锁和行锁的占用情况(以下为测试环境)。一般情况主要看Innodb_row_lock_current_waits，Table_locks_waited。行锁和表锁的等待时长。同时也要关注下Innodb_row_lock_time_avg平均行锁获取锁的时间（单位毫秒）。当时排除了表锁，并且排查了应用的request日志的请求，请求的sql log中没有引发表锁的SQL记录。
'Com_lock_tables','0'
'Com_unlock_tables','0'
'Handler_external_lock','12'
'Innodb_row_lock_current_waits','0'
'Innodb_row_lock_time','52030'
'Innodb_row_lock_time_avg','3716'
'Innodb_row_lock_time_max','51004'
'Innodb_row_lock_waits','14'
'Key_blocks_not_flushed','0'
'Key_blocks_unused','6696'
'Key_blocks_used','3'
'Locked_connects','0'
'Performance_schema_locker_lost','0'
'Performance_schema_metadata_lock_lost','0'
'Performance_schema_rwlock_classes_lost','0'
'Performance_schema_rwlock_instances_lost','0'
'Performance_schema_table_lock_stat_lost','0'
'Qcache_free_blocks','1'
'Qcache_total_blocks','1'
'Table_locks_immediate','452'
'Table_locks_waited','0'
接下来继续查看运行的线程信息，为了检查问题SQL。
$show full processlist 通过DB的排查还是意外收获了一些可以优化的repository方法（属于业务正常范围的乐观锁异常，但还是会影响性能）。不过，还不是能解决问题的根本。
排查JVM
因为使用的是JPA,检查了一下应用的基础配置，最大active连接数是80，最大等待时间5s。如上文log，确实达到了该服务获取连接的上限。默认的理解上是确实有一些线程占用了连接。
$jstack -l pid
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):
"elasticsearch[Oneg the Prober][listener][T#1]" #221 daemon prio=5 os_prio=0 tid=0x00007fc2a418a800 nid=0x195 waiting on condition [0x00007fc28318d000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000e29f88d0> (a java.util.concurrent.LinkedTransferQueue)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
...............省略.........也没有很多对于repository的调用。有获取连接的线程。但慢慢可以确定的是，连接池释放的问题。
排查代码
翻了下hibernate对于连接池释放的代码。找到了rg.hibernate.internal.SessionFactoryImpl对于连接池的release_mode的设置,其通过org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl的如下代码：
private ConnectionReleaseMode determineConnectionReleaseMode(
JdbcConnectionAccess jdbcConnectionAccess,
boolean isUserSuppliedConnection,
ConnectionReleaseMode connectionReleaseMode) {
if ( isUserSuppliedConnection ) {
return ConnectionReleaseMode.ON_CLOSE;
}
else if ( connectionReleaseMode == ConnectionReleaseMode.AFTER_STATEMENT &&
! jdbcConnectionAccess.supportsAggressiveRelease() ) {
LOG.debug( "Connection provider reports to not support aggressive release; overriding" );
return ConnectionReleaseMode.AFTER_TRANSACTION;
}
else {
return connectionReleaseMode;
}
}可以追溯到connectionReleaseMode的默认值被设置成了”ON_CLOSE”,也即当前hibernate版本的默认值。目前系统使用的5.0.12.final版本。而HIbernate最新版本5.2.17中。ConnectionReleaseMode的默认值是“AUTO”。
先说明一下Hibernate对于Jdbc的Session管理，主要是通过SessionFactoryImpl，release_mode配置会影响连接池释放的模式，除了用户自定义的实现。
ConnectionReleaseMode是一个枚举类。最新版本的四种释放模式如下:
- auto：默认。 对于JTATransactionFactory来说，会设置成AFTER_STATEMENT;对JDBCTransactionFactory来说，则是AFTER_TRANSACTION。
- on_close：Hibernate session在第一次需要进行JDBC操作的时候获取连接，然后持有它，直到session关闭。该模式只存在于老的版本，新版本中代码里存在主要是为了向下兼容。
- after_transaction:在事务执行完成后释放连接。这一设置不能在JTA环境下使用。也要注意，使用ConnectionReleaseMode.AFTER_TRANSACTION的时候，假若session 处于auto-commit状态，连接会像AFTER_STATEMENT那样被释放。
- after_statement：jdbc连接在每次语句执行后释放连接，只能用于JTA环境。
解决
1. 升级hibernate-core版本,添加配置如下：
spring.jpa.properties.hibernate.connection.release_mode=AUTO如果不升级，也可以根据选择的事务环境进行after_transaction，after_statement的调整。on_close在新版本中已经废弃，所以不建议再使用。
2. 后续的优化
调整配置可以优化连接池的使用效率，但是还是需要优化sql。当时的业务有比较大规模的并发写（update and insert都有），触发了update的乐观锁以及insert的自动增长锁(AUTO-INC Locks). 读的场景基本都是走search,所以需要结合业务场景持续优化。
总结
线上问题第一要务是止损。排查的路径很重要，偶尔谢谢总结也可以再加深一些理解。