问题描述
有时应用程序最终无响应.今天，我用jstack -F检查了线程状态，并且在本地代码中有多个线程被卡在c3p0连接上:
Sometimes the application ends up unresponsive. Today I checked the thread status with jstack -F and there were multiple threads stuck in native code for c3p0 connection :
Thread 14060: (state = IN_NATIVE)
- java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
- java.net.SocketInputStream.read(byte[], int, int, int) @bci=79, line=150 (Compiled frame)
- java.net.SocketInputStream.read(byte[], int, int) @bci=11, line=121 (Compiled frame)
- com.mysql.jdbc.util.ReadAheadInputStream.fill(int) @bci=262, line=114 (Compiled frame)
- com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(byte[], int, int) @bci=176, line=161 (Compiled frame)
- com.mysql.jdbc.util.ReadAheadInputStream.read(byte[], int, int) @bci=48, line=189 (Compiled frame)
- com.mysql.jdbc.MysqlIO.readFully(java.io.InputStream, byte[], int, int) @bci=34, line=3036 (Compiled frame)
- com.mysql.jdbc.MysqlIO.reuseAndReadPacket(com.mysql.jdbc.Buffer, int) @bci=23, line=3489 (Compiled frame)
- com.mysql.jdbc.MysqlIO.reuseAndReadPacket(com.mysql.jdbc.Buffer) @bci=3, line=3478 (Compiled frame)
- com.mysql.jdbc.MysqlIO.checkErrorPacket(int) @bci=12, line=4019 (Compiled frame)
- com.mysql.jdbc.MysqlIO.sendCommand(int, java.lang.String, com.mysql.jdbc.Buffer, boolean, java.lang.String, int) @bci=428, line=2490 (Compiled frame)
- com.mysql.jdbc.MysqlIO.sqlQueryDirect(com.mysql.jdbc.StatementImpl, java.lang.String, java.lang.String, com.mysql.jdbc.Buffer, int, int, int, boolean, java.lang.String, com.mysql.jdbc.Field[]) @bci=559, line=2651 (Compiled frame)
- com.mysql.jdbc.ConnectionImpl.execSQL(com.mysql.jdbc.StatementImpl, java.lang.String, int, com.mysql.jdbc.Buffer, int, int, boolean, java.lang.String, com.mysql.jdbc.Field[], boolean) @bci=130, line=2677 (Compiled frame)
- com.mysql.jdbc.ConnectionImpl.execSQL(com.mysql.jdbc.StatementImpl, java.lang.String, int, com.mysql.jdbc.Buffer, int, int, boolean, java.lang.String, com.mysql.jdbc.Field[]) @bci=17, line=2627 (Compiled frame)
- com.mysql.jdbc.StatementImpl.executeQuery(java.lang.String) @bci=534, line=1556 (Compiled frame)
- com.mysql.jdbc.DatabaseMetaData$9.forEach(java.lang.Object) @bci=174, line=5013 (Compiled frame)
- com.mysql.jdbc.IterateBlock.doForAll() @bci=25, line=51 (Compiled frame)
- com.mysql.jdbc.DatabaseMetaData.getTables(java.lang.String, java.lang.String, java.lang.String, java.lang.String[]) @bci=280, line=4991 (Compiled frame)
- com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnectionNoQuery(java.sql.Connection, java.lang.Throwable[]) @bci=21, line=185 (Compiled frame)
- com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(java.sql.Connection, java.lang.String, java.lang.Throwable[]) @bci=7, line=62 (Compiled frame)
- com.mchange.v2.c3p0.AbstractConnectionTester.activeCheckConnection(java.sql.Connection) @bci=4, line=67 (Compiled frame)
- com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(java.lang.Object) @bci=122, line=368 (Compiled frame)
- com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(java.lang.Object) @bci=26, line=310 (Compiled frame)
- com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run() @bci=35, line=1999 (Interpreted frame)
- com.mchange.v2.async.ThreadPerTaskAsynchronousRunner$TaskThread.run() @bci=41, line=255 (Interpreted frame)
如果未设置其他任何连接测试，DefaultConnectionTester.activeCheckConnectionNoQuery似乎会检查DatabaseMetaData.getTables.
DefaultConnectionTester.activeCheckConnectionNoQuery seems to check DatabaseMetaData.getTables if no other connection testing is set up.
C3p0手册包含有关配置正确的连接测试和包含有关Play的c3p0设置的说明！但我想知道:
C3p0 manual has instructions for configuring proper connection testing and this answer has instructions for c3p0 settings with Play! but I'm wondering:
- 有什么方法可以检查出这是什么问题吗?
- 在结果出现之前，我遇到的标准"Mysql连接将在8小时后被终止"
- Is there some way to check out what's the issue behing this?
- The standard "Mysql connection being killed after 8 hours" I've encountered before results as an exception
- 我有一种预感，默认情况下c3p0不进行连接测试
- 默认值idleConnectionTestPeriod = 0，testConnectionOnCheckin = false，testConnectionOnCheckout = false
- I have a hunch that by default c3p0 doesn't do connection testing
- default values idleConnectionTestPeriod = 0, testConnectionOnCheckin = false, testConnectionOnCheckout = false
- 例如，即使我配置了一些明智的preferredTestQuery，是否存在由于当前getTables()调用而导致该查询也挂起的风险?
我们将c3p0.automaticTestTable设置为具有更明智的连接测试，但这似乎并不能解决问题，只是稍微更改了线程的堆栈跟踪.
We set c3p0.automaticTestTable to have more sensible connection testing but that didn't seem to fix the problem, just changing a bit the stack trace for the threads.
在类似情况下，我们现在具有以下线程堆栈:
In similar case, we now have thread stack as following:
"Task-Thread-for-com.mchange.v2.async.ThreadPerTaskAsynchronousRunner@6064cd08" daemon prio=10 tid=0x00007f53d403a000 nid=0x63dd runnable [0x00007f53dce4a000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:150) at java.net.SocketInputStream.read(SocketInputStream.java:121) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) - locked <0x00000000dbecd0d8> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2677) - locked <0x00000000dbec1a70> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2627) at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1556) - locked <0x00000000dbec1a70> (a com.mysql.jdbc.JDBC4Connection) - locked <0x00000000d1330078> (a com.mysql.jdbc.StatementImpl) at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:73) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:374) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:310) at com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:1999) at com.mchange.v2.async.ThreadPerTaskAsynchronousRunner$TaskThread.run(ThreadPerTaskAsynchronousRunner.java:255)播放线程正在等待建立数据库连接:
Play threads were waiting to get a DB connection:
"play-thread-3" prio=10 tid=0x00007f53c400b000 nid=0x5b3e in Object.wait() [0x00007f53ddd57000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000000db9f38f8> (a com.mchange.v2.resourcepool.BasicResourcePool) at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:579) - locked <0x00000000db9f38f8> (a com.mchange.v2.resourcepool.BasicResourcePool) at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:584) ... (näitä vaihtelevat määrät) at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:584) - locked <0x00000000db9f38f8> (a com.mchange.v2.resourcepool.BasicResourcePool) at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:584) - locked <0x00000000db9f38f8> (a com.mchange.v2.resourcepool.BasicResourcePool) at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128) at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160) at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81) at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473) at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60) at play.db.jpa.JPAPlugin.startTx(JPAPlugin.java:377) at play.db.jpa.JPAPlugin.beforeInvocation(JPAPlugin.java:345) at play.plugins.PluginCollection.beforeInvocation(PluginCollection.java:473) at play.Invoker$Invocation.before(Invoker.java:217) at play.Invoker$Invocation.run(Invoker.java:277) at play.server.PlayHandler$NettyInvocation.run(PlayHandler.java:229) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722)一些注意事项:
- (至少在理论上)可能有很多连接恰好在读取堆栈转储的同时进行了测试，尽管我发现这不太可能.
- 在另一个问题有人提到数据死锁或硬件/网络问题可能会导致这种行为.
- 至少不应进行任何正在进行的模式修改.
- It IS possible (at least in theory) that many connections just happen to be tested the same time as the stack dump is readed, even though I find this unlikely.
- In another question it was mentioned that data deadlocks or hardware/network problems might cause this kind of behaviour.
- At least there shouldn't be any ongoing schema modification.
br，Touko
对自己的回答:
- 未找到连接挂起的原因:(
- RDS具有MySQL的error.log，不幸的是那里没有任何内容
- No reason found for the connection hanging :(
- RDS has error.log for MySQL, unfortunately nothing there
- idleTimeExcessConnections:来自application.conf db.pool.maxIdleTimeExcessConnections(默认为0)
- checkoutTimeout:来自application.conf db.pool.timeout(默认值为5000)
- idleConnectionTestPeriod:10
- setTestConnectionOnCheckin:true
- 此外，conf/c3p0.properties可用于设置自定义属性
我们将继续设置c3p0.automaticTestTable并稍后检查是否有任何问题.
We will proceed with setting c3p0.automaticTestTable and check out whether there will be any problems later.
更新:不幸的是，我们还没有解决问题:(同样，使用AutomaticTestTable时，连接测试似乎卡住了java.net.SocketInputStream.socketRead0(Native Method)
UPDATED : Unfortunately we didn't get rid of problems yet :( Also with automaticTestTable the connection testing seems to have get stuck java.net.SocketInputStream.socketRead0(Native Method)
再次对自己回答:
我们最终尝试使用c3p0:s maxAdministrativeTaskTime .这有点骇人听闻，所以必须看看这是否可以作为最终解决方案(如果可行).
We ended up trying this "set timeout for connection testing query" approach with c3p0:s maxAdministrativeTaskTime. This is a bit of a hack so got to see whether this can be the final solution (if it works).
到目前为止，还没有问题，我们将看看它是如何工作的.日志中也没有c3p0错误/堆栈跟踪，我希望这种中断会显示在日志中吗?要么尚未发生超时，要么我们应该调整日志记录配置以显示c3p0日志.
So far no problems yet, we'll see how this works. No c3p0 errors / stack traces in the log either, I'd expect this interruption to be shown in the logs? Either timeout hasn't occurred yet or we should tune logging configuration to get c3p0 logs shown.
UPDATE(2013-04-04):在此之后，这个问题(可能)不是那么频繁发生，而是时不时地发生:(
UPDATE (2013-04-04) : After this the problem (probably) hasn't occurred so often but has occurred every now and then :(
推荐答案
再次回答自己:
我们首先使用为MySQL驱动程序指定的socketTimeout结束，以便不会卡住连接测试.
We ended first up using socketTimeout specified for MySQL driver so so that connection test doesn't get stuck.
似乎底层的TCP连接结束了，因此服务器没有响应(TCP ACK或其他任何内容).
It seems that the underlying TCP connections ended up so that that there is no answer from the server (TCP ACK or anything).
更新:最终的解决方案是通过提供tcpdump来提供对AWS的支持，他们发现了AWS基础架构中的某些情况.他们建议我们在EC2实例的安全组中打开临时端口范围. AWS论坛.
UPDATE: The final solution was got with giving tcpdump for AWS support, they found out some case within AWS infrastructure. They adviced us to open the ephemeral port range in our EC2 instance's security group. More discussion at AWS forum.
这篇关于连接偶尔会因Amazon RDS MySQL& Play Framework 1.2.5(c3p0默认设置)的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持！