<0x00000007957d27d8> (a org.apache.commons.dbcp.BasicDataSource): 0 Thread(s) sleeping, 803 Thread(s) waiting, 1 Thread(s) locking
803개의 Thread를 locking 하고 있는 DBCP의 MultiConnectionManager Class
at coperframe.common.data.impl.MutiConnectionManager.getConnection(MutiConnectionManager.java:74)
그렇다면
동일한 Thread가 Lock을 잡고 있어서 일까?
아래를 보면 10초 사이에 5회에 kill 3으로 생성한 Thread dump 마다 lock을 잡고 있는 Thrad를 추려보았다.
각각 다른 Thread 이다.
결국은 하나의 처리가 오래 걸리면서 DBPool을 Lock 하고 이로 인하여 다른 Thread들이 대기 하는 상태로 Dead Lock은 아니고 느리게 처리되고 있는 상황으로 확인 할 수 있다.
"
ajp-0.0.0.0-12501-379" daemon prio=10 tid=0x00007fee78239800 nid=0x70d runnable [0x00007fee5203f000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.NSProtocol.connect(Unknown Source)
"ajp-0.0.0.0-12501
-33" daemon prio=10 tid=0x00007fee78048000 nid=0x7b14 runnable [0x00007fee87921000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.NSProtocol.connect(Unknown Source)
at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.
java:844)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnecti"ajp-0.0.0.0-12501-818" daemon prio=10
"ajp-0.0.0.0-12501
-348" daemon prio=10 tid=0x00007fee7820e800 nid=0x55d runnable [0x00007fee528a0000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.DataPacket.receive(Unknown Source)
"ajp-0.0.0.0-12501
-793" daemon prio=10 tid=0x00007fee78516800 nid=0x1086 runnable [0x00007fee4b20d000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.NSProtocol.connect(Unknown Source)
at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.
java:844)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.
java:268)
at oracle.jdbc.driver.PhysicalConnection. (PhysicalConnection.
java:420)
"ajp-0.0.0.0-12501
-818" daemon prio=10 tid=0x00007fee78532800 nid=0x11de runnable [0x00007fee4b087000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Sourc
coperframe은 개발사 Framework로써 JBoss DB Pool을 사용하지 않고 있음
사실 framework의 문제라기 보다는 해당 Common DBCP의 고전적인 Thread safety 문제일 것으로 판단되나
DBCP를 분석하고 싶지 않아서 PASS함.
이때 문제점은 두 가지 이다.
- Thread 처리가 느리다 = SQL이 느린것일 것이다. 쿼리 처리가 빨랐다면 좀 밀려도 대충대충 운영되고 있었겠지만 처리시간이 요청되는 속도 보다 느리기 때문에 결국 전체적으로 처리가 밀린것으로 보면 되겠다.
- 현 시스템으로 마이그레이션 하기전 기존 사이트에서는 이상 없었다는 말이 여기서 나온다. 기존 시스템에서도 Jennifer로 보면 Active Thread가 30~50개 까지 쌓여 있는것을 볼 수 있었다. (정상적이라면 Active Thread는 10개 이상 올라갈 일이 없다.)
- 이것은
- 기존 DB가 이전한 DB보다 빠르게 응답을 했다는 의미일 수 있고
- 이번에 튜닝을 가이드하면서 WEB/WAS 구간에서의 병목을 해결해 버림으로써 DB로 전보다 높은 부하가 들어가서 DB응답성능이 떨어진것으로 도 생각할 수 있다.
- DB Pool이 Thread safe 하다는 것은 병목이다.
- DB Pool에 getConnection을 하고 Connection을 받으면 해당 객체를 release 해야 한다. 자기가 처리가 끝날때 까지 Pool을 lock 하는 것이 문제다.
- 각각의 Thread가 getConnection을 하고 받은 connection으로 처리를 했다면 SQL처리가 느려서 밀리거나 Connection이 모두 소진되는 문제가 발생 할 수 있으나 이번에서는 Lock 문제로 발견되게 된 것이다. (http://stackoverflow.com/questions/12339726/multithreading-with-apache-dbcp)
- 짐작하기에 commonDBCP를 사용하면서 발생하지 않았을까 판단한다. 설명은 링크를 참고한다.(http://blog.naver.com/PostView.nhn?blogId=myca11&logNo=80127605636&beginTime=0&jumpingVid=&from=search&redirect=Log&widgetTypeCall=true)
== 가해자 Thread
"ajp-0.0.0.0-12501-379" daemon prio=10 tid=0x00007fee78239800 nid=0x70d runnable [0x00007fee5203f000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method) <== Read0 는 대부분 DB에 query를 보내고 대기하고 있는 상황을 의미함
at java.net.SocketInputStream.read(SocketInputStream.
java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.NSProtocol.connect(Unknown Source)
at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.
java:844)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.
java:268)
at oracle.jdbc.driver.PhysicalConnection. (PhysicalConnection.
java:420)
at oracle.jdbc.driver.T4CConnection. (T4CConnection.
java:165)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:35)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.
java:801)
at org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.
java:582)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.
java:840)
- locked <0x0000000798a1b9e8> (a org.apache.commons.pool.impl.GenericObjectPool)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.
java:106)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.
java:1044)
at coperframe.common.data.impl.MutiConnectionManager.getConnection(MutiConnectionManager.java:74)
- locked <0x00000007957d27d8> (a org.apache.commons.dbcp.BasicDataSource)
at coperframe.common.work.impl.DefaultWorkerManager.executeWorker(DefaultWorkerManager.java:61)
at coperframe.common.struts.ActionHandler.callService(ActionHandler.java:42)
at coperframe.common.struts.ActionHandler.callStaticService(ActionHandler.java:29)
at coperframe.common.struts.WorkerAction.callService(WorkerAction.
java:161)
at coperframe.common.struts.WorkerAction.execute(WorkerAction.
java:114)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.
java:413)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.
java:225)
at org.apache.struts.action.ActionServlet.process(ActionServlet.
java:1858)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.
java:446)
at javax.servlet.http.HttpServlet.service(HttpServlet.
java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.
java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at com.tomato.com.http.HttpResponseHeaderFilter.doFilter(HttpResponseHeaderFilter.java:95)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at com.tomato.sso.sp.AuthFilter.doFilter(AuthFilter.java:47)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.
java:235)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.
java:191)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.
java:183)
at org.jboss.web.tomcat.service.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.
java:135)
at org.jboss.web.tomcat.service.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:94)
at org.jboss.web.tomcat.service.session.JvmRouteValve.invoke(JvmRouteValve.java:88)
at org.jboss.web.tomcat.service.session.LockingValve.invoke(LockingValve.java:62)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.
java:126)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.
java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.
java:102)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.
java:158)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.
java:109)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.
java:330)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.
java:437)
at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.
java:385)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.
java:451)
at java.lang.Thread.run(Thread.
java:662)
=피해자 Thread
ajp-0.0.0.0-12501-33" daemon prio=10 tid=0x00007fee78048000 nid=0x7b14 waiting for monitor entry [0x00007fee87922000]
java.lang.Thread.State: BLOCKED (on object monitor)
at coperframe.common.data.impl.MutiConnectionManager.getConnection(MutiConnectionManager.java:74)
- waiting to lock <0x00000007957d27d8> (a org.apache.commons.dbcp.BasicDataSource)
at coperframe.common.work.impl.DefaultWorkerManager.executeWorker(DefaultWorkerManager.java:61)
at coperframe.common.struts.ActionHandler.callService(ActionHandler.java:42)
at coperframe.common.struts.ActionHandler.callStaticService(ActionHandler.java:29)
at coperframe.common.struts.WorkerAction.callService(WorkerAction.
java:161)
at coperframe.common.struts.WorkerAction.execute(WorkerAction.
java:114)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.
java:413)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.
java:225)
at org.apache.struts.action.ActionServlet.process(ActionServlet.
java:1858)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.
java:446)
at javax.servlet.http.HttpServlet.service(HttpServlet.
java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.
java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at com.tomato.com.http.HttpResponseHeaderFilter.doFilter(HttpResponseHeaderFilter.java:95)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at com.tomato.sso.sp.AuthFilter.doFilter(AuthFilter.java:47)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.
java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.
java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.
java:235)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.
java:191)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.
java:183)
at org.jboss.web.tomcat.service.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.
java:135)
at org.jboss.web.tomcat.service.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:94)
at org.jboss.web.tomcat.service.session.JvmRouteValve.invoke(JvmRouteValve.java:88)
at org.jboss.web.tomcat.service.session.LockingValve.invoke(LockingValve.java:62)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.
java:126)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.
java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.
java:102)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.
java:158)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.
java:109)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.
java:330)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.
java:437)
at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.
java:385)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.
java:451)
at java.lang.Thread.run(Thread.
java:662)