0002721: mysql connection pool connections are not being put back into the pool when used in PHP (quercus)

Mantis - Quercus
Viewing Issue Advanced Details

ID:	Category:	Severity:	Reproducibility:	Date Submitted:	Last Update:
2721		major	sometimes	06-06-08 11:33	09-08-08 14:18

Reporter:	paulberto	Platform:
Assigned To:	ferg	OS:
Priority:	normal	OS Version:
Status:	closed	Product Version:	3.1.6
Product Build:		Resolution:	fixed
Projection:	none
ETA:	none	Fixed in Version:	3.2.1

Summary:	0002721: mysql connection pool connections are not being put back into the pool when used in PHP (quercus)
Description:	I had to implement a hack by adding max-active-time to the database parameters in resin-web.xml -- OTHERWISE the connections would hang in open state forever. I can see that they are finished because in mysql i can see the same database connections IDLE. So right now -- i get a whole lot of these in my logs: [21:07:27.640] closing pool item from active timeout:PoolItem[jdbc/cam,164,ManagedConnectionImpl] [21:07:42.701] closing pool item from active timeout:PoolItem[jdbc/cam,296914,ManagedConnectionImpl] Obviously because it is hitting the max-active-time of 15 seconds which is high .. I wana remove this workaround.
Steps To Reproduce:
Additional Information:	Ended up rewriting all the db calls in java and calling them from a quercus module which fixed a lot of the issues .. also reinforcing the fact that there is a serious bug with php/quercus/mysql. using the recommended mysql j/connector version 3.1.14 -- also tried the latest version 5.x with no success. Also -- just to mention -- this is not happening all the time-- only under load.. IE, i am unable to reproduce it with a simple test ... the connections do get put back in the pool with a simple test. Just under load is a problem.
Relationships
Attached Files:

Notes

This problem is of significant nature. All I see in my logs are:

[01:18:08.313] com.caucho.quercus.QuercusException: java.io.InterruptedIOException: timeout fd=963 errno=11
[01:18:08.313]
[01:18:08.313] at com.caucho.quercus.program.TextStatement.execute(TextStatement.java:69)
[01:18:08.313] at com.caucho.quercus.program.QuercusProgram.execute(QuercusProgram.java:272)
[01:18:08.313] at com.caucho.quercus.page.InterpretedPage.execute(InterpretedPage.java:70)
[01:18:08.313] at com.caucho.quercus.env.Env.include(Env.java:3735)
[01:18:08.313] at com.caucho.quercus.expr.IncludeExpr.eval(IncludeExpr.java:86)
[01:18:08.313] at com.caucho.quercus.program.ExprStatement.execute(ExprStatement.java:64)
[01:18:08.313] at com.caucho.quercus.program.BlockStatement.execute(BlockStatement.java:105)
[01:18:08.313] at com.caucho.quercus.program.QuercusProgram.execute(QuercusProgram.java:272)
[01:18:08.313] at com.caucho.quercus.page.InterpretedPage.execute(InterpretedPage.java:70)
[01:18:08.313] at com.caucho.quercus.page.QuercusPage.executeTop(QuercusPage.java:119)
[01:18:08.313] at com.caucho.quercus.servlet.ResinQuercusServlet.service(ResinQuercusServlet.java:149)
[01:18:08.313] at com.caucho.quercus.servlet.QuercusServlet.service(QuercusServlet.java:355)
[01:18:08.313] at javax.servlet.http.HttpServlet.service(HttpServlet.java:91)
[01:18:08.313] at com.caucho.server.dispatch.ServletFilterChain.doFilter(ServletFilterChain.java:103)
[01:18:08.313] at com.caucho.server.cache.CacheFilterChain.doFilter(CacheFilterChain.java:150)
[01:18:08.313] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:187)
[01:18:08.313] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[01:18:08.313] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:270)
[01:18:08.313] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:678)
[01:18:08.313] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[01:18:08.313] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[01:18:08.313] at java.lang.Thread.run(Thread.java:619)
[01:18:08.313] Caused by: java.io.InterruptedIOException: timeout fd=963 errno=11
[01:18:08.313]
[01:18:08.313] at com.caucho.vfs.JniSocketImpl.writeNative(Native Method)
[01:18:08.313] at com.caucho.vfs.JniSocketImpl.write(JniSocketImpl.java:288)
[01:18:08.313] at com.caucho.vfs.JniStream.write(JniStream.java:124)
[01:18:08.313] at com.caucho.vfs.WriteStream.nextBuffer(WriteStream.java:327)
[01:18:08.313] at com.caucho.server.connection.ResponseStream.writeNext(ResponseStream.java:480)
[01:18:08.313] at com.caucho.server.connection.ToByteResponseStream.write(ToByteResponseStream.java:336)
[01:18:08.313] at com.caucho.vfs.VfsStream.write(VfsStream.java:201)
[01:18:08.313] at com.caucho.vfs.WriteStream.print(WriteStream.java:553)
[01:18:08.313] at com.caucho.vfs.WriteStream.print(WriteStream.java:631)
[01:18:08.313] at com.caucho.quercus.program.TextStatement.execute(TextStatement.java:63)
[01:18:08.313] ... 21 more
[01:18:08.702] java.io.InterruptedIOException: timeout fd=1019 errno=11
[01:18:08.702]
[01:18:08.702] at com.caucho.vfs.JniSocketImpl.writeNative(Native Method)
[01:18:08.702] at com.caucho.vfs.JniSocketImpl.write(JniSocketImpl.java:288)
[01:18:08.702] at com.caucho.vfs.JniStream.write(JniStream.java:124)
[01:18:08.702] at com.caucho.vfs.WriteStream.flushBuffer(WriteStream.java:393)
[01:18:08.702] at com.caucho.server.connection.AbstractHttpResponse.finish(AbstractHttpResponse.java:2201)
[01:18:08.702] at com.caucho.server.connection.AbstractHttpResponse.close(AbstractHttpResponse.java:279)
[01:18:08.702] at com.caucho.server.webapp.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:286)
[01:18:08.702] at com.caucho.server.webapp.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:108)
[01:18:08.702] at com.caucho.server.dispatch.ForwardFilterChain.doFilter(ForwardFilterChain.java:84)
[01:18:08.702] at com.caucho.server.cache.CacheFilterChain.doFilter(CacheFilterChain.java:150)
[01:18:08.702] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:187)
[01:18:08.702] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[01:18:08.702] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:270)
[01:18:08.702] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:678)
[01:18:08.702] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[01:18:08.702] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[01:18:08.702] at java.lang.Thread.run(Thread.java:619)
[01:18:09.448] closing pool item from active timeout:PoolItem[jdbc/cam,1037098,ManagedConnectionImpl]
[01:18:09.448] closing pool item from active timeout:PoolItem[jdbc/cam,1037096,ManagedConnectionImpl]
[01:18:09.448] closing pool item from active timeout:PoolItem[jdbc/cam,1037072,ManagedConnectionImpl]
[01:18:09.448] closing pool item from active timeout:PoolItem[jdbc/cam,1036735,ManagedConnectionImpl]
[01:18:09.448] closing pool item from active timeout:PoolItem[jdbc/cam,1036733,ManagedConnectionImpl]
... thousands of times

This is happening only from quercus code ....... Please advise ... At this point it seems that quercus is not fit for any production environment. Please see my notes above .. Perhaps it is due to some other error while processing the php page and then the db connection never gets put back into the pool at the end.. we tried everything including forcing mysql_close().

Unsure if those interuption exceptions have anything to do with it .. This is a very heavily loaded system. We've been using quercus for few weeks now and this problem has been here since day one.

Please advise!!!!