WLS9.2 이상의 JDBC Connection leak profiling
문제.
Oracle WebLogic Server는 JDBC Connection의 Leak 여부를 감지하고, 애플리케이션에서 leak connection을 유발하는 stacktrace를 log에 출력하며, auto close해주는 기능을 가지고 있다.
이 기능을 수행하는 옵션이 기존 버전(WLS8.x 이하)과 달리 WLS9.x부터 Diagnostic framework의 개념이도입되면서 수정되었다.
우선은, WLS에서 말하는 “Automatically Recovering Leaked Connections”의 개념과 WLS8.x와 비교하여WLS9.x이상부터 설정하는 방법에 대해 알아본다.
WLS8.x VS WLS9.x의 설정 방법.
1. WLS8.x의 설정 방법.
Services -> JDBC-> Connection Pools -> 설정할 Connection Pool 이름 -> Connections tab -> Enable Connection Leak Profiling 체크2. WLS9.x이후 버전 설정 방법.
1) Profile Connection Leak
많은 사용자들이 혼돈하는 사항이다. 실제 위의 옵션의 의미는 다음과 같다. 해당 옵션은 data source로부터 획득한 connection을 보유하고 있는 Thread와 connection leaked된 정보를 수집한다. 이 옵션을 통해서는 leaked된 connection이 Connection Pool에 반환되는 것이 아니라 leaked된 connection을 정보를 수집하여 Diagnostic의 Data로 사용하거나 WLS log 파일에 출력하는데 사용된다.
2) Inactive Connection Timeout
JDBC의 Leaked Connection은 datasource의 Connection Pool에 정상적으로 반환되지 않는 Connection을의미한다. - 이러한 Leaked Connection을 자동으로 회수하기 위해서는, 사용자는 관리 콘솔의 “JDBC Data Source>Configuration>Connection Pool” 페이지에서 “Inactive Connection Timeout”의 속성을 정의해야 한다. 해당 옵션의 값이 설정되면, WebLogic Server는 사용자가 정의한 시간 동안 Reserved Connection이 아무런 활동이 없는 경우 data source에 해당 connection을 강제적으로 반환해 준다. 이 옵션의 기본값은 “0”이며, 이 값의 의미는 해당 기능이 OFF상태임을 의미한다.
추가적으로, 만일 사용자 프로그램에서 모든 statement 문을 close 하고 connection 만 닫지 않은 경우connection leak 이 detect되지 않을 것이다. 이 문제는 WLS9.1~WLS10.0MP1에서만 발생하여 이를 해결하기 위해서는 CR314547패치를 적용해야 한다. 해당 패치에 대한 상세 내용은 아래를 참조하라.
CR314547 - WLS 9.2 MP1 - JDBC connection leak not detected
- DIAGNOSIS:
In the wrapper Statement internalClose()method we mistakenly nullify the local variable conn so that we can't set the connection not-in-use in the postInvoke() method after JDBC call has competed. The connection will be thought in the middle of call forever and the pool will never retract it therefor connection leaking happens.
- RESOLUTION:
Now we do not nullify conn in the internalClose()method of Statement
- RELEASE NOTE:
Now JDBC connection leak will be detected if all statements are closed but the connection is not released. |
WLS9.x에서 leak connection 이 recovering 될 때 나타나는 로그 파일에 추가되는 내용이다.
즉, leak 이라고 판단되는 Connection을 "Inactive Connection Timeout"에 설정된 값 이후 자동으로 회수할때 아래의 내용이 로그에 출력될 것이다. 사용자는 해당 로그를 통해 잘못된 로직을 수정해야 한다.
<2009. 9. 24 오후 7시 21분 22초 ACT> <Warning> <JDBC> <BEA-001153> <Forcibly releasinginactive conn
ection "[weblogic.jdbc.wrapper.JTAConnection_weblogic_jdbc_wrapper_XAConnection_oracle_jdbc_driver_L
ogicalConnection-ora920DS-1, oracle.jdbc.driver.LogicalConnection@1f36af6]" back into the connection
pool "ora920DS", currently reserved by: java.lang.Exception |
참고 자료.
WAS에 배포된 애플리케이션들이 DB작업을 하는데 있어서 WAS 제품에 의해 제공된 커넥션 풀의 상황에 대한 모니터링을 해준다.
웹로직 서버에 배포된 애플리케이션들은 제공되는 Data Source를 가지고 DB에 접근하게된다.
Data Source는 커넥션 풀을 가지고 있으며, ....
==============================================================================
다양한 문제 사례
==============================================================================
1. 특정 서버에 대한 cpu 사용률이 다른 서버에 비해 월등히 높다. (모든 서버가 동일 업무처리)
접근키워드: 특정 서버, cpu 사용률
특정 서버가 문제가 되는것은 WAS 앞단에서 전달을 잘못했다.
cpu 사용률이 높아지는 업무에는 DB, ...등이 있다.
2. 쓰레드는 놀고있는데 현재 사용중인 DB connection은 너무 많다.
접근키워드:
쓰레드가 놀고있다. -> 부하는 그리 많지 않다. 또는 부하가 있더라도 처리가 빨리되서 쓰레드가 빨리 반납된다.
DB connection이 너무 많다. -> 실제 DB업무가 많다. 또는 쓰지도 않으면서 커넥션만 맺어져있다.
관리자는 Data Source에 대한 모니터링을 통해 뭘 할 수 있을까?
쓰레드와 Data Source 모니터링을 통해 쓰레드와 커넥션의 개수를 산정한다.
connection leak이 발생하는 것을 추측할 수 있다.
쓰레드는 놀고 있는데, connection 사용량이 생각보다 많다면 connection leak을 예상할 수 있다.
정확하게 connection leak 여부를 판단하기 위해서는 다음의 두가지가 필요하다.
inactive connection timeout값 설정
profiling connection leak 옵션 enable
만약 connection leak이 발생하면 weblogic server log에 connection leak이 감지되었음을 알리는 로그가 남게된다.
Data Source와 Data Source를 사용하는 서버 인스턴스별로 아래 항목이 각각 보여지게 된다.
동일한 Data Source에서 Active Connections Average Count가 특별하게 높은 서버 인스턴스에 대해서
해당 서버가 해당 DS(Data Source)를 처리하는 업무가 많다. (DB 접근 업무가 많다)
만약 3대의 서버가 동일 업무를 처리하는데 특정 서버의 Active Connections Average Count가 높다면,
앞단의 L4, 웹서버등의 로드밸런서(부하분산기)가 부하분산을 제대로 못했거나 재수없게 DB 업무가 해당 서버에 몰린다고 볼 수 있다.
| DataSource 모니터링 화면의 항목 | 자료형 | 한글 설명 |
| Server | 고정값 | DataSource가 배포되어 있는 Server명 |
| Active Connections Average Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Active Connection의 평균값
- Avg(Active Connections Current Count) |
| Active Connections Current Count | 현재 조회값 | 현재 사용 중인 Connection 개수 |
| Active Connections High Count | 기동후 최대값 | 기동 후부터 조회한 시점까지의 Active Connection의 최대값
- Max(Active Connection Current Count) |
| Connection Delay Time | 기동후 누적값 | millisecond 단위로 DB와의 물리적인 연결하는데 걸린 평균 시간값
- Avg(DB Connection 연결 시간들) |
| Connections Total Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 DB Connection이 생성된 총횟수
- Sum(Create DB Connection) |
| Current Capacity | 현재 조회값 | 현재 연결되어 있는 DB Connection 개수 |
| Curr Capacity High Count | 기동후 최대값 | 기동 후부터 조회한 시점까지의 Current Capacity의 최대값
- Max(Current Capacity) |
| Enabled | 고정값 | DataSource의 Enabled/Disabled의 상태 |
| Failed Reserve Request Count | 기동후 누적값 | 해당 DS에서 요청을 받았지만 수행되지 못한 누적 수
|
| Failures To Reconnect Count | 기동후 누적값 | 해당 DS가 DB Connection refresh를 시도해서 실패한 수. DB가 unavailable 이거나 DB로의 network connection이 원활하지 않은 경우 refresh가 실패할 수 있음 |
| Highest Num Available | 기동후 최대값 | 기동 후부터 조회한 시점까지의 Num Available의 최대값
- Max(Num Available) |
| Leaked Connection Count | 현재 조회값 | close()하지 않은 누수된 Connection 개수 |
| Num Available | 현재 조회값 | 현재 사용할 수 있는 DataSource 개수 |
| Num Unavailable | 현재 조회값 | 현재 사용할 수 없는 DataSource 개수 |
| PrepStmt Cache Access Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Statement Cache에 Access한 총횟수로 각 Connection마다의 Access한 횟수의 총합계 |
| Prep Stmt Cache Add Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Statement Cache에 Add한 총횟수로 각 Connection 마다의 Add한 횟수의 총합계 |
| Prep Stmt Cache Current Size | 현재 조회값 | 기동 후부터 조회한 시점까지의 각 Connection의 Statement Cache의 크기의 총합계 |
| Prep Stmt Cache Delete Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Statement Cache에 Delete한 총횟수로 각 Connection 마다의 Delete한 횟수의 총합계
- Statement Cache가 full 상태에서 새로운 Statement를 Add하려고 할 때 Statement Cache Delete가 발생함 |
| Prep Stmt Cache Hit Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Statement Cache의 해당 Statement가 있었던 총횟수 |
| Prep Stmt Cache Miss Count | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Statement Cache의 해당 Statement가 없었던 총횟수 |
| Reserve Request Count | 기동후 누적값 | Connection을 요청한 총 횟수 |
| State | 현재 조회값 | DataSource의 상태 : Running/Suspended/Shutdown/Unhealthy/Unknown |
| JDBC Driver | 고정값 | JDBC Driver명 |
| Wait Seconds High Count | 기동후 누적값 | connection 을 얻기 위해 가장 오래 기다린 시간 |
| Waiting For Connection Current Count | 현재 조회값 | 현재 Connection을 얻기 위해서 기다리고 있는 개수 |
| Waiting For Connection Failure Total | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Connection을 받기 위해서 기다렸으나 Connection을 얻지 못한 횟수의 총합계
- Sum |
| Waiting For Connection High Count | 기동후 최대값 | 기동 후부터 조회한 시점까지의 Connection을 받기 위해서 기다렸던 횟수의 최대값
- Max(Waiting For Connection Current Count) |
| Waiting For Connection Success Total | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Connection을 받기 위해서 기다리고 성공적으로 Connection을 얻은 횟수의 총합계 |
| Waiting For Connection Total | 기동후 누적값 | 기동 후부터 조회한 시점까지의 Connection을 받기 위해서 기다렸던 횟수의 총합계
|
기능설명
JDBC Connection Pool Leak - Stack Trace 설정 옵션
Version | 설정항목 | 기능 |
Weblogic 8.x | 1) Enable Connection Leak Profiling | - Leak Message & Stack Trace 생성 - 설정시간 초과되는 JDBC Pool 회수(idle 상태로 회수) - Weblogic 서버로그에 생성 |
Weblogic 9 higher | 1) Profile Connection Leak 2) Inactive Connection Timeout |
- Weblogic 9.0 이후부터 Profile Connection Leak + Inactive Connection Timeout 까지같이 설정할 경우 Inactive connection Timeout시간이 되면 서버로그에 stack trace 내용까지 표시된 후 JDBC Connection Pool을 회수 함.
- Weblogic 8.x 까지는 Enable Connection Leak Profiling을 설정함.
적용하여 검증된 사항으로, 시스템 성능에 영향을 주지 않으므로 구성 시 적용하는 것을 권고
옵션특징
옵션 | 특이사항 |
< Weblogic 8.x > Enable Connection Leak Profiling < Weblogic 9 higher > Profile Connection Leak | < Weblogic 9 higher > - 이 옵션만 설정 시 Leak Message 만 생성 |
< Weblogic 9 higher > Inactive Connection Timeout | - Stack trace 까지 보기위해 설정필요 - 설정 시 application 처리시간을 확인하여 적용필요 즉, JDBC 업무처리 시간이 최대 120초이고 초과 시 비정상으로 판단되면 120 ~ 121 수치적용 |
Weblogic 10 Version 에 따라 Inactive Connection Timeout 설정 시 JDBC Driver에 따라 다음과 같이 메시지가 표시된다
Weblogic Version | XA Driver | Non-XA Driver |
9.x 이상 | Warning 경고만 발생 메시지가 표시 되지 않을 때 System.out을추가 | 서버로그 확인 |
- XA Driver 의 경우 메시지가 표시되지 않는 경우가 있으며 이러한 경우 소스 Exception 부분에 System.out.println 부분을 추가하여 확인할 수 있다.
- Non-XA Driver 의 경우 메시지 표시가 된다.
설정방법
ㅇ Profile Connection Leak
Weblogic Console --> Services --> Data Sources --> 해당 Data Source 선택 -->
Configuration --> Diagnostics -->
ㅇ Inactive Connection Timeout
Weblogic Console --> Services --> Data Sources --> 해당 Data Source 선택 -->
Configuration --> Connection Pool --> Advanced
로그예시
Non-XA dirver Stack 표시
<2011. 4. 11 오전 8시 16분 16초 KST> <Warning> <JDBC> <BEA-001153> <Forcibly rel easing inactive connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_dri ver_T4CConnection@2d" back into the connection pool "jdbcDS", currently reserved by: java.lang.Exception at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:318) at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:344) at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:322) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:438) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:317) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:93) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:106) at weblogic.jdbc.pool.Driver.connect(Driver.java:149) at weblogic.jdbc.jts.Driver.getNonTxConnection(Driver.java:652) at weblogic.jdbc.jts.Driver.connect(Driver.java:127) at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:355) at jsp_servlet.__test_noxa._jspService(__test_noxa.java:96) … at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300) at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183) … at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121) at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1446) at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201) at weblogic.work.ExecuteThread.run(ExecuteThread.java:173) .> |
XA dirver 사용 시 Stack 이 안보이는 일부경우(보일때도 있으며 안보이는 경우도 있다.)
<2011. 4. 11 오후 1시 40분 23초 KST> <Warning> <Common> <BEA-000620> <Forcibly r eleasing inactive resource "autoCommit=true,enabled=true,isXA=true,isJTS=false,v endorID=0,connUsed=false,doInit=false,'null',destroyed=false,poolname=jdbcXADS,a ppname=null,moduleName=null,connectTime=32,dirtyIsolationLevel=false,initialIsol ationLevel=2,infected=false,lastSuccessfulConnectionUse=1302496634640,secondsToT rustAnIdlePoolConnection=10,currentUser=null,currentThread=null,lastUser=null,cu rrentError=null,currentErrorTimestamp=null,JDBC4Runtime=true,supportStatementPoo lable=true,needRestoreClientInfo=false,defaultClientInfo={},supportIsValid=true" back into the pool "jdbcXADS".> |
Source 상에 Exception 부분에 System.out.println 부분을 추가하여Stack 표시
java.sql.SQLException: Internal error: Cannot obtain XAConnection weblogic.commo n.resourcepool.ResourceLimitException: No resources currently available in pool jdbcXADS to allocate to applications, please increase the size of the pool and r etry.. at weblogic.common.resourcepool.ResourcePoolImpl.reserveResourceInternal (ResourcePoolImpl.java:577) at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:342) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:419) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:324) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:94) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:63) at weblogic.jdbc.jta.DataSource.getXAConnectionFromPool(DataSource.java:1677) at weblogic.jdbc.jta.DataSource.refreshXAConnAndEnlist(DataSource.java:1445) at weblogic.jdbc.jta.DataSource.getConnection(DataSource.java:446) at weblogic.jdbc.jta.DataSource.connect(DataSource.java:403) at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:364) at jsp_servlet.__test_xa._jspService(__test_xa.java:101) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227) …. at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120) at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2277) at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2183) at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1454) at weblogic.work.ExecuteThread.execute(ExecuteThread.java:207) at weblogic.work.ExecuteThread.run(ExecuteThread.java:176) |
<2011. 4. 11 오후 2시 19분 11초 KST> <Warning> <Common> <BEA-000620> <Forcibly r eleasing inactive resource "autoCommit=true,enabled=true,isXA=true,isJTS=false,v endorID=0,connUsed=false,doInit=false,'null',destroyed=false,poolname=jdbcXADS,a ppname=null,moduleName=null,connectTime=47,dirtyIsolationLevel=false,initialIsol ationLevel=2,infected=false,lastSuccessfulConnectionUse=1302499081281,secondsToT rustAnIdlePoolConnection=10,currentUser=java.lang.Exception at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:310) at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:344) at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:322) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:431) at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:316) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:93) at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:61) at weblogic.jdbc.jta.DataSource.getXAConnectionFromPool(DataSource.java:1584) … at weblogic.jdbc.wrapper.Statement.close(Statement.java:390) at jsp_servlet.__test_xa._jspService(__test_xa.java:120) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227) at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125) … at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121) at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2202) at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2108) at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1432) at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201) at weblogic.work.ExecuteThread.run(ExecuteThread.java:173) ,currentThread=null,lastUser=null,currentError=null,currentErrorTimestamp=null,J DBC4Runtime=true,supportStatementPoolable=true,needRestoreClientInfo=false,defau ltClientInfo={},supportIsValid=true" back into the pool "jdbcXADS".> |
