i have a web application using tomcat 7 (latest version) running on a windows 2012 server. The web app has some simple forms for logging in a user and sending private messages. The database calls are made with EclipseLink 2.5.0 using the JPA API, with a RESOURCE_LOCAL configuration.
My Problem is that after a while (1-2 days), my web app becomes unresponsive to any user action. There are no error messages, neither on the client nor at the server side. But when i investigate the tomcat with JConsole, i can see many threads in a "blocked" or waitung state. Here is the stacktrace at which the thread hangs:
<pre>
Name: http-apr-0.0.0.0-80-exec-9
State: BLOCKED on org.eclipse.persistence.logging.DefaultSessionLog@a17eaf8 owned by: http-apr-0.0.0.0-80-exec-3
Total blocked: 1 Total waited: 68
Stack trace:
org.eclipse.persistence.logging.DefaultSessionLog.log(DefaultSessionLog.java:138)
org.eclipse.persistence.internal.sessions.AbstractSession.log(AbstractSession.java:3484)
org.eclipse.persistence.internal.sessions.AbstractSession.log(AbstractSession.java:4673)
org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:615)
org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:558)
org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1995)
org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:570)
org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:248)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:299)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:694)
org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2714)
org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2667)
org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:477)
org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1155)
org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:899)
org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1114)
org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:402)
org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1202)
org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2894)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1797)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1779)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1744)
org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:258)
org.eclipse.persistence.internal.jpa.QueryImpl.getSingleResult(QueryImpl.java:516)
org.eclipse.persistence.internal.jpa.EJBQueryImpl.getSingleResult(EJBQueryImpl.java:400)
org.cs.LoginServlet.login(LoginServlet.java:80)
org.cs.LoginServlet.doPost(LoginServlet.java:43)
javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:611)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked org.apache.tomcat.util.net.SocketWrapper@1fd672f
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:724)
</pre>
It seems that the threads hangs during EclipseLink writing log messages to the console. Has anyone encountered this behaviour? For me, it's hard to believe that logging could lead to a deadlock. I also haven't found any resources on the web describing this "anomaly". Would be glad if someone could point me in some direction since i am totally stuck in this problem.
UPDATE 21.12.2013
Here is the thread to which the lock points to. It seems that it is somewhere deep in the PrintStream classes, reinforcing my suspicion that it is a problem with concurrent access to an output buffer while logging some stuff. I use several servlets so i have different threads but the logging is only done by EclipseLink and Tomcat. Do i have to synchronize all my methods to prevent the deadlocking?
Name: http-apr-0.0.0.0-80-exec-2
State: RUNNABLE
Total blocked: 0 Total waited: 37
Stack trace:
java.io.FileOutputStream.writeBytes(Native Method)
java.io.FileOutputStream.write(FileOutputStream.java:318)
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked java.io.BufferedOutputStream@4412b0a0
java.io.PrintStream.write(PrintStream.java:482)
- locked java.io.PrintStream@2709fb4a
sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked java.io.OutputStreamWriter@50cb4c
java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
java.io.PrintStream.write(PrintStream.java:527)
- locked java.io.PrintStream@2709fb4a
java.io.PrintStream.print(PrintStream.java:669)
java.io.PrintStream.println(PrintStream.java:806)
- locked java.io.PrintStream@2709fb4a
org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:264)
org.eclipse.persistence.sessions.server.ConnectionPool.acquireConnection(ConnectionPool.java:206)
- locked org.eclipse.persistence.sessions.server.ConnectionPool@34dc0be5
org.eclipse.persistence.sessions.server.ServerSession.getAccessors(ServerSession.java:538)
org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:557)
org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:248)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:299)
org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:694)
org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2714)
org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2667)
org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:477)
org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1155)
org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:899)
org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1114)
org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:402)
org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1202)
org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2894)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1797)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1779)
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1744)
org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:258)
org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:468)
org.cs.UserServlet.getPopularUsers(UserServlet.java:105)
org.cs.UserServlet.doPost(UserServlet.java:45)
javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:611)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked org.apache.tomcat.util.net.SocketWrapper@4bb13b2e
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:724)