在setautocommit阶段,我的spring jpa/hibernate应用程序(在tomcat 8上运行)将在尝试从mysql读取时挂起5-30秒,这是一个反复出现的间歇性问题。这发生在我们运行mysql 5.0时,在升级到最新的mariadb后仍在继续。
这个问题可能一次出现几天或几周,但当它出现时,通常是在下午,月日,在我们的“高峰”时间。(这里的“峰值”非常轻,可能每秒10个请求)奇怪的是,这个问题经常发生在14:50,尽管我找不到任何cronjob或其他会导致这种情况的重复任务。
应用程序在两个服务器上集群,两个服务器在尝试连接到共享数据库服务器时同时挂起,因此它似乎是数据库端的东西。db允许1000个max_连接,但远没有这么多。在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。

最佳答案

它没有。堆栈跟踪显示它在尝试从数据库服务器读取数据时被阻止,这意味着它已经连接,它正在做的是设置autoCommit,而不是连接阶段的任何事情。

10-08 18:28
查看更多