common DBCP 사용시 Thread lock 문제 - CASE2

또다른 CASE는 아래 링크 클릭하면 볼 수 있다. (두개 다 동일한 문제라고 보면 됨)
http://yckwon2nd.blogspot.kr/2014/04/common-dbcp-thread-lock.html

1. 증상
WAS의 Thread가 모두 소진되어 서비스가 되지 않거나 그에 의한 여파(처리가 안되면 모든 객체가 대기 되므로)로 Full GC가 발생하여 서비스 지연 또는 안되는 현상

2. 원인
Apache org에서 제공되는 Common DBCP module은 Thread 안정성을 위해서 Single Thread로 동작합니다.
간략하게 설명하면
Connection 하나를 APP가 받아서 사용할 때 Pool 자체에 대한 접근을 차단 하게되며
APP가 느릴 경우 다른 Connection을 요구하는 모든 APP가 정지 되는현상 (Thrad Lock wait)이 발생합니다.
보내준 내용을 보면 1Thread에 의해 670개의 요청이 대기 상태가 됨을 알 수 있음
<0x00000000c00c6070> (a org.apache.commons.dbcp.AbandonedObjectPool):    0 Thread(s) sleeping, 670 Thread(s) waiting, 1 Thread(s) locking

3. 해결
Tomcat의 경우 Common DBCP가 아닌 tomcat에 포함된 Tomcat DBCP를 사용하거나
Jboss, Weblogic 등의 엔터프라이즈 WAS를 사용할 경우 해당 제품에서 제공되는 DB Pool을 사용하여 해결 가능함

{
PC에서 똑딱거리면서 하겠다고 DBCP로 개발하는건 좋은데 
제발 Production환경으로 가면서 WAS Pool안쓰고 버티는 똥배짱좀 부리지 말자 
Framework 쓰자나... conf 파일 하나 바꿔서 JNDI  Lookup만 맞춰주면 되는데
대체  왜그래....
}

4. 설명
아래 thread를 보면 APP가 Altibase DB로 쿼리 수행 후 시간이 지연되어 대기 중인 상태임
이때 볼드 처리된 라인을 보면 DB Connection Pool에 대하여 Lock을 획득했는데 처리가 늦어지면서 해당 객체를 돌려주지 못함
(common DBCP는 single thread로 동작하기 때문에 이렇게 됨)
일반적으로 Common DBCP를 사용하면
- locked <0x00000007957d27d8> (a org.apache.commons.dbcp.BasicDataSource)
와 같이 BasciDatasource가 lock되나 아래에 보면
- locked <0x00000000c00c6070> (a org.apache.commons.dbcp.AbandonedObjectPool)
으로 이름이 다름

이유는 DBCP에서 Connection 의 비정상 회수 시 일정시간 후에 Connection을 폐기하도록 하는 Abandone설정을 활성화하면
다른 Class가 사용되므로 Thread 정보에서 다르게 보일 수 있으나 원인과 증상은 동일함

Thread-1184" daemon prio=10 tid=0x00007fa2b8010000 nid=0x2112 runnable [0x00007fa24d2d0000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:218)
        at sun.nio.ch.IOUtil.read(IOUtil.java:186)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:359)
        - locked <0x00000000c0659998> (a java.lang.Object)
        at Altibase.jdbc.driver.cmnTCP.recv(cmnTCP.java:276)
        at Altibase.jdbc.driver.cmp.flush(cmp.java:294)
        at Altibase.jdbc.driver.cmp.writeDirectExecuteAndFetchReq(cmp.java:1227)
        - locked <0x00000000c0619b78> (a Altibase.jdbc.driver.cmp)
        at Altibase.jdbc.driver.ABConnection.writeDirectExecuteFetchReq(ABConnection.java:624)
        at Altibase.jdbc.driver.ABStatement.executeQuery(ABStatement.java:321)
        - locked <0x00000000ce0fe9b8> (a Altibase.jdbc.driver.ABStatement)
        at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
        at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
        at org.apache.commons.dbcp.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:332)
        at org.apache.commons.dbcp.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:312)
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:855)
        - locked <0x00000000c00c6070> (a org.apache.commons.dbcp.AbandonedObjectPool)
        at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
        at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
        at devonframework.persistent.connection.LJndiDataSource.if(Unknown Source)
...이하 생략


PS. 피해자들 과 잘못된 접근시 삽질 Sequence

{
아래같은 Thread가  670개 대기중 --> 
제니퍼에서 보면 Active Eq에 670개 쌓여서 뻘겋게 보임 --> 
670개 요청이 메모리를 잡아먹고 버티니 WAS Heap이 남아도는 사이트가 아니라면 Full GC가 지속적으로 발생 --> 
Full GC 정보 보고 Heap memory 부족한거 아니냐고 개드립시작함....  --> 
(기타 : WAS Thread 가 모자라다, DB Connection이 부족하다 등의 개드립도 있음)
메모리 덤프떠서 메모리 분석 한다 -->
메모리에 보면 졸라 다양한 APP들이 이상한 객체를 만들고 있고 DB Connection 관련 Object가 엄청 많다(메모리 내용으로는 뭐가 문제인지 알 수 가 없다.)  -->
DB Connection 또는 Pool이 버그라고 개드립 -->
제품 버그 찾는다고 구글링 십년....  -->
잘못하면 삼천포에 빠져죽는다...

약은 약사에게 병은 의사에게....
}

"Thread-1730" daemon prio=10 tid=0x00007fa2b0103800 nid=0xc29 waiting for monitor entry [0x00007fa23c1c1000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.commons.pool.impl.GenericObjectPool.getNumIdle(GenericObjectPool.java:911)
        - waiting to lock <0x00000000c00c6070> (a org.apache.commons.dbcp.AbandonedObjectPool)
        at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:78)
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
        at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
        at devonframework.persistent.connection.LJndiDataSource.if(Unknown Source)
        at devonframework.persistent.connection.LDataSourcePool.getJNDIConnection(Unknown Source)
        at devonframework.persistent.connection.LDataSourcePool.getConnection(Unknown Source)
        at devonframework.persistent.dao.LConnectionManager.getConnection(Unknown Source)
        at devonframework.business.transaction.LConnectionMapper.getConnection(Unknown Source)
        at devonframework.persistent.autodao.LAutoDao.getConnection(Unknown Source)
        at devonframework.persistent.autodao.LCommonDao.executeQueryForSingle(Unknown Source)
        at devon.batch.core.persistence.BatchDao$JobInfo.retrieveSingleJobGroup(Unknown Source)
        at devon.batch.core.persistence.BatchDao$JobInfo.retrieveSingleJobGroup(Unknown Source)
        at devon.batch.core.persistence.BatchDao$JobInfo.retrieveJobGroupDescriptor(Unknown Source)
        at devon.batch.scheduler.trigger.JobGroupExecOrder.beforeSend(JobGroupExecOrder.java:106)
        at devon.batch.scheduler.trigger.AbstractTransferOrder.send(AbstractTransferOrder.java:93)
        at devon.batch.scheduler.manager.SchedulerManager.sendJobGroupExecOrder(SchedulerManager.java:179)
        at devon.batch.scheduler.manager.LSchedulerItem.doIt(LSchedulerItem.java:70)
        at devonframework.service.scheduler.job.LJob$1.run(Unknown Source)