2014년 4월 30일 수요일

common DBCP 사용시 Thread lock 문제

WAS에서 제공하는 DB Pool을 사용하지 않고
Apache Common DBCP를 사용하는 곳에서 가끔 DB Connection이 밀리는 현상으로 고생하는곳이 있다.

Common DBCP는 Thread Safe하기 위해서 Connection Pool을 Lock 하고 처리를 진행한다.

이건 해당 Thread의 처리 시간이 오래 걸리면 결국 다른 Thread들은 Connection Pool에 접근할 수 없다는 의미이다.

이 문제를 해결하는 가장 간편한 방법은 tomcat DBCP jar파일을 찾아서 바꿔버리면 해결된다.

tomcat다운로드 받아서 lib 폴더에 tomcat-dbcp.jar 를 찾아서 자신의 WAR에 추가하고

기존의 commons-dbcp-1.4jar, commons-pool-1.6.jar, commons-collections-3.2.1-bin.zip  등은 뻬버리자  (tomcat jar 안에 다 들어있다.)

org.apache.commons.dbcp.BasicDataSource  같이 commons로 된 놈이 있으면 아래같이 바꾸자
org.apache.tomcat.dbcp.dbcp.BasicDataSource

(버젼 문제도 안될 수 도 있다. 나에게 따지지 마라 ㅋㅋㅋ)

아니면 Frame work 나 자신의 DB Connection Manager 에서 JNDI Lookup 부분을 찾아서 WAS가 제공하는 DBPool로 바꾸어 주어도 된다.

설마 아직도 bean 이나 servlet에서 Connection 하는 사람은 없겠지....
Framework나 잘 구성된 Manager class를 사용하고 있다면
WAS Pool로 소스를 변경하는 일이 기능적으로는 큰 일이 아니다.

두려움....

혹시나....

어쩌겠는가...내가 할 수 있는일은 솔루션을 제공할 뿐 바꿔드릴 수 는 없음임  (하기 싫음 -.-)

여하간 삽질 하는 누군가에게는 도움이 되길 기원하며...



  1. 이슈
    1. DB Connection을 늘렸음에도 APP들이 getConnection에서 대기하고 있음
      1. DB Connection을 90개로 늘렸음
      2. Application getConnection에서 대기하기는 하지만 제니퍼에서 보면 DB Connection이 모두 사용되고 있는것은 아님
  2. 분석내용
    1. Thread Dump
      1. 특정 Thread가 DataSource를 Lock 하고 풀리지 않아서 다른 모든 APP들이 getConnection에서 대기하고 있음
      1. 해당 문제상태에서 Thread lock 상태 설명

        Icon
        <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함.
        이때 문제점은 두 가지 이다.
        1. Thread 처리가 느리다 = SQL이 느린것일 것이다. 쿼리 처리가 빨랐다면 좀 밀려도 대충대충 운영되고 있었겠지만 처리시간이 요청되는 속도 보다 느리기 때문에 결국 전체적으로 처리가 밀린것으로 보면 되겠다. 
          1. 현 시스템으로 마이그레이션 하기전 기존 사이트에서는 이상 없었다는 말이 여기서 나온다. 기존 시스템에서도 Jennifer로 보면 Active Thread가 30~50개 까지 쌓여 있는것을 볼 수 있었다. (정상적이라면 Active Thread는 10개 이상 올라갈 일이 없다.)
          2. 이것은 
            1. 기존 DB가 이전한 DB보다 빠르게 응답을 했다는 의미일 수 있고
            2. 이번에 튜닝을 가이드하면서 WEB/WAS 구간에서의 병목을 해결해 버림으로써 DB로 전보다 높은 부하가 들어가서 DB응답성능이 떨어진것으로 도 생각할 수 있다.
        2. DB Pool이 Thread safe 하다는 것은 병목이다.
          1. DB Pool에 getConnection을 하고 Connection을 받으면 해당 객체를 release 해야 한다. 자기가 처리가 끝날때 까지 Pool을 lock 하는 것이 문제다.
          2. 각각의 Thread가 getConnection을 하고 받은 connection으로 처리를 했다면 SQL처리가 느려서 밀리거나 Connection이 모두 소진되는 문제가 발생 할 수 있으나 이번에서는  Lock 문제로 발견되게 된 것이다. (http://stackoverflow.com/questions/12339726/multithreading-with-apache-dbcp)
          3. 짐작하기에 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)

    4. 조치사항
      1. DB Lock 상태로 인하여 DB Connection을 다 쓰지도 못하고 App들이 정지상태로 대기하는 형태임을 설명해줌
      2. 개발팀에서 framework에서 DBCP를 빼고 JBoss DB Pool로 변경함
      3. JBoss DB Pool 설정 지원

작성자: 시간:
라벨:

댓글 2개:

본 블로그의 댓글은 검토후 등록됩니다.

피드 구독하기: 댓글 (Atom)