为什么 Tomcat 在 MySQL 上尝试 setAutoCommit 时会挂起？

Question

我有一个反复出现的间歇性问题，在 setAutoCommit 阶段，我的 Spring JPA/Hibernate 应用程序（在 Tomcat 8 上运行）在尝试从 MySQL 读取数据时会挂起 5-30 秒。这发生在我们运行 MySQL 5.0 时，升级到最新的 MariaDB 后仍然存在。

该问题可能不会连续几天或几周出现，但一旦出现，通常是在我们“高峰”时段的 M 至 Th 下午。 （这里的“峰值”非常轻，可能每秒 10 个请求。）奇怪的是，这个问题经常发生在 14:50，尽管我找不到任何会导致这种情况的 cronjobs 或其他重复性任务。

该应用程序集群在两台服务器上，并且两台服务器在尝试连接到共享数据库服务器时同时挂起，所以它似乎是数据库端的东西。 db 允许 1000 个 max_connections，但使用量远不及那么多。在 Tomcat 方面，我使用的 C3P0 最大连接数为 100。似乎没有任何特定的 SQL 触发该问题，在此问题发生时所有查询都挂起。

这是挂起线程的堆栈跟踪：

"ajp-nio-8010-exec-26" Id=1355 RUNNABLE (in native)
  java.lang.Thread.State: RUNNABLE
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
   at java.net.SocketInputStream.read(SocketInputStream.java:170)
   at java.net.SocketInputStream.read(SocketInputStream.java:141)
   at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
   at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
   at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@33d807d4
   at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2911)
   at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3332)
   at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3322)
   at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3762)
   at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
   at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
   at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2531)
   - locked com.mysql.jdbc.JDBC4Connection@178ec6c
   at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4852)
   - locked com.mysql.jdbc.JDBC4Connection@178ec6c
   at com.intergral.fusionreactor.jdbc.ConnectionSurrogate.setAutoCommit(ConnectionSurrogate.java:368)
   at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:1059)
   etc.....

同时，在 MySQL 的慢查询日志中：

# Time: 160128 14:50:38
# User@Host: user @ server1
# Thread_id: 77244  Schema: db_live  QC_hit: No
# Query_time: 7.621437  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 0
SET timestamp=1454010638;
commit;
# User@Host: user @ server2
# Thread_id: 81339  Schema: db_live  QC_hit: No
# Query_time: 7.556022  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 0
SET timestamp=1454010638;
commit;

我不太确定如何处理慢日志 - 这里没有实际的 SQL，但它对应于此时在 Tomcat 上观察到的 7 秒挂起。与两台服务器试图同时连接并相互阻止有关吗？两个SET timestamp 语句完全相同。请注意，两个 Tomcat 实例都使用相同的用户凭据登录，只是来自两个不同的 IP。日志中附近没有其他慢查询，之前或之后。

有什么想法可能导致此问题或下一步该往哪里看？

编辑：

其他可能值得注意的细节：表是 InnoDB，我们使用的是transaction-isolation = READ-COMMITTED。所有挂起的线程都在等待 setAutoCommit。

Answer 1

它没有。堆栈跟踪显示它阻塞试图从数据库服务器读取，这意味着它已经连接，并且它正在做的是设置autoCommit，在连接阶段没有任何东西。