Resolve grails jetty hangs problem caused by commons dbcp
Recently, I'm developing a website by grails.
Few days ago, I found a problem, the web server hangs after requesting the homepage.
The latest change is that the homepage is requesting 15+ articles instead of just 2 articles.
For development environment, the articles are stored in mysql.
The article is retrieved by requesting another link article controller,
and the related code in ArticleController.groovy looks like this,... ...
def article = Article.get(id) //#1
if(article){
def info = articleService.retrieveInfo(article) //#2
}
... ...
code #1, finds the article instance from mysql db.
code #2, articleService is a grails service in grails-app/services directory.
the retrieveInfo method retrieves some info from the given article instance without any db operation.
The homepage should show 15+ articles, so the code above runs 15+ times in 15+ separate http request threads.
And then the grails embedded web server jetty HANGS. no more response.
After deploy the application in tomcat, tomcat hangs too.
What's the problem?
I guess it may due to thread deadlock, but how?
First, I got the java thread dump,
//redirect console output to a fileyichao src $ grails run-app > console.txt 2>&1
//after requesting homepage, press ctrl+\ (or kill -QUIT <pid>) to generate Java thread dump.
I found many threads are waiting on and locked the same monitor 0x96c6de90.
this is the code snippet, it's btpool0-15 thread, btpool0-14~2 threads are just the same.
"btpool0-15" prio=10 tid=0x08a76800 nid=0x22e4 in Object.wait() [0x8f2f2000..0x8f2f60c0]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x96c6de90> (a org.apache.commons.pool.impl.GenericObjectPool)
at java.lang.Object.wait(Object.java:485)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:748)
- locked <0x96c6de90> (a org.apache.commons.pool.impl.GenericObjectPool)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:540)
at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
......
at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.invokeMethodN(ScriptBytecodeAdapter.java:170)
at ArticleController.xxxx(ArticleController.groovy:85)
......
at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
at org.mortbay.jetty.Server.handle(Server.java:295)
at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:503)
at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:827)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:511)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:210)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:379)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:361)
at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
the ArticleController.groovy:85 code is the code #2 above.
This time, I found that in grails, when we define "boolean transactional = true" in ArticleService.groovy.
articleService.retrieveInfo() method opens a connection even if we have no db operation.
so every single thread tries to open mysql connection twice by code #1 and #2 above.
But we are just open connection and only select data from mysql, why hangs?
The code waits at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:748)
Thanks to apache, I can easily download the source code, and the line 748 is,public Object borrowObject() throws Exception {
........
synchronized(this) {
........
switch(_whenExhaustedAction) {
........
case WHEN_EXHAUSTED_BLOCK:
try {
if(_maxWait <= 0) {
wait(); //#line 748
} else {
wait(_maxWait);
}
...........
see #line 748, we got this, in GenericObjectPool.borrowObject() method, if connections in pool exhausted, it will block.
The default active connections limit is 10, but we have 15+ thread, so all block!
Actually it should not to be like this. And Indeed it's already filed bug for apache commons dbcp 1.2.1.
The grails 1.0.3 is just using commons-dbcp-1.2.1.jar.
you can find this bug at https://issues.apache.org/jira/browse/DBCP-260
PS:
In grails, calling any methods in transactional-enabled services will try to open a db connection.
So only call methods in transactional-enabled services if they are related to db operation and really need transaction.
Put all other methods in transactional-disabled services or normal groovy in src/groovy/*.groovy files.
This resolves the problem above successfully.
BTW, The transaction is enabled by default in grails 1.0.3.
