APM Agent에 의해 성능지연이 발생한 APPL 개선

잡부·2023년 3월 15일

AIX APPL IBM JAVA apm websphere 성능튜닝

현상

WAS의 CPU 및 자원 사용률은 낮지만, 지속적인 지연이 발생

환경

AIX 6.1
IBM Java JRE 1.4.2
websphere 6

접근방법

스택트레이스를 생성 해 어느부분이 지연을 발생시키는지 확인 하기로 함.
- 오라클/HP 계열 버전 1.5 이상 : jstack [pid]
- 오라클/HP 계열 버전 1.5 이하 : kill -3 [pid] <- 표준 출력으로 스레드 덤프를 출력
- IBM 계열 : kill -3 [pid] <- 호출할 때마다 javacore.[날짜].[시간].[PID].[번호]/txt 형식으로 파일이 생성 됨

IBM Java는 Kill -3 을 통해 스택을 수집할 수 있기 때문에, 실행중인 JVM의 환경 변수를 확인후 스택을 수집 함.

APPLserver:[/Logs/javacore]ps eww [pid] | tr ' ' '\012' | grep IBM
IBM_HEAPDUMP=TRUE  // kill -3 [PID]로 힙 덤프를 남길 수 있게 함
IBM_HEAPDUMP_OUTOFMEMORY=TRUE // OutOfMemory 발생 시 힙 덤프를 남기게 함
IBM_JAVACORE_OUTOFMEMORY=true // OutOfMemory 발생 시 자바 덤프를 남기게 함
IBM_HEAP_DUMP=TRUE
IBM_HEAPDUMPDIR=/Logs/javacore // 자바 덤프와 힙 덤프를 남길 디렉터리를 지정함

프로세스의 수행 환경 확인

AIX : ps eww [pid] | tr ' ' '\012' | grep =

리눅스 : cat /proc/[pid]/environ | tr \0 \n 또는 ps eww [pid]

솔라리스 : /usr/ucb/ps -wwwe [pid]

HP-UX : gdb를 실행한 후 해당 프로세스를 붙여 p ((char**)_environ)[0]@30 수행(30은 개수

윈도우 :로세스 탐색기 → 대상 프로세스를 더블클릭(프로세스 상세 화면) → Environment 탭 선택

스택을 분석하니 해당 APPL는 Connection Pool 방식이 아닌, Drivermanger을 통해 JDBC getConnection을 하는 방식 이었다. IBM자바 이기도 하고, JAVA버전이 낮아서 클레스 락, 객체 락이 명확하게 보이진 않았지만, Natvie Stack에 mutex_lock 정보를 확인하고 synchronized 처리 돼 있음을 짐작 했다.

3XMTHREADINFO      "WebContainer : 98" (TID:0x3037CCE8, sys_thread_t:0x8396BF28, state:CW, native ID:0xCE19) prio=5
4XESTACKTRACE          at java.sql.DriverManager.getConnection(Unknown Source) 락 대기자
4XESTACKTRACE          at test.frame.j2ee.SCDataSourceProxy.getJDBCConnection(SCDataSourceProxy.java(Compiled Code))
4XESTACKTRACE          at test.frame.j2ee.SCEjbBean.getJDBCConnection(SCEjbBean.java(Compiled Code))
                                                              .
                                                              .
4XESTACKTRACE          at com.ibm._jsp._fileDownLoad2._jspService(_fileDownLoad2.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.jsp.runtime.HttpJspBase.service(HttpJspBase.java(Compiled Code))
4XESTACKTRACE          at javax.servlet.http.HttpServlet.service(HttpServlet.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.wsspi.webcontainer.servlet.GenericServletWrapper.handleRequest(GenericServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.jsp.webcontainerext.JSPExtensionServletWrapper.handleRequest(JSPExtensionServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewInformation(HttpInboundLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.requestComplete(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.attemptIO(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.workerRun(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager$Worker.run(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java(Compiled Code))
3XHNATIVESTACK       Native Stack
NULL                 ------------
3XHSTACKLINE         at 0xD051126C in _mutex_lock
3XHSTACKLINE         at 0xD0526868 in _cond_wait_local
3XHSTACKLINE         at 0xD0526E28 in _cond_wait
3XHSTACKLINE         at 0xD0527910 in pthread_cond_timedwait
3XHSTACKLINE         at 0xD48D4130 in condvarTimedWaitUpTo248Days
3XHSTACKLINE         at 0xD48D42C0 in condvarTimedWait
3XHSTACKLINE         at 0xD48D30A8 in sysMonitorWait
3XHSTACKLINE         at 0xD4789F68 in lkMonitorEnter
3XHSTACKLINE         at 0xD49482C8 in _jit_monitorEnterQuicker
3XHSTACKLINE         at 0xD4B3A93C in JITSigSegvHandler

3XMTHREADINFO      "WebContainer : 94" (TID:0x3037CF08, sys_thread_t:0x836AFCA8, state:CW, native ID:0xCA15) prio=5
4XESTACKTRACE          at java.sql.DriverManager.getConnection(Unknown Source) 락 대기자
4XESTACKTRACE          at test.frame.j2ee.SCDataSourceProxy.getJDBCConnection(SCDataSourceProxy.java(Compiled Code))
4XESTACKTRACE          at test.frame.j2ee.SCEjbBean.getJDBCConnection(SCEjbBean.java(Compiled Code))
                                                              .
                                                              .
4XESTACKTRACE          at com.ibm._jsp._fileDownLoad2._jspService(_fileDownLoad2.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.jsp.runtime.HttpJspBase.service(HttpJspBase.java(Compiled Code))
4XESTACKTRACE          at javax.servlet.http.HttpServlet.service(HttpServlet.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.wsspi.webcontainer.servlet.GenericServletWrapper.handleRequest(GenericServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.jsp.webcontainerext.JSPExtensionServletWrapper.handleRequest(JSPExtensionServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewInformation(HttpInboundLink.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.requestComplete(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.attemptIO(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager.workerRun(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.tcp.channel.impl.WorkQueueManager$Worker.run(WorkQueueManager.java(Compiled Code))
4XESTACKTRACE          at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java(Compiled Code))
3XHNATIVESTACK       Native Stack
NULL                 ------------
3XHSTACKLINE         at 0xD051126C in _mutex_lock
3XHSTACKLINE         at 0xD0526868 in _cond_wait_local
3XHSTACKLINE         at 0xD0526E28 in _cond_wait
3XHSTACKLINE         at 0xD0527910 in pthread_cond_timedwait
3XHSTACKLINE         at 0xD48D4130 in condvarTimedWaitUpTo248Days
3XHSTACKLINE         at 0xD48D42C0 in condvarTimedWait
3XHSTACKLINE         at 0xD48D30A8 in sysMonitorWait
3XHSTACKLINE         at 0xD4789F68 in lkMonitorEnter
3XHSTACKLINE         at 0xD49482C8 in _jit_monitorEnterQuicker
3XHSTACKLINE         at 0xD4B3A93C in JITSigSegvHandler

3XMTHREADINFO      "WebContainer : 6" (TID:0x3035C260, sys_thread_t:0x78613228, state:R, native ID:0x70B1) prio=5
4XESTACKTRACE          at java.net.SocketInputStream.socketRead0(Native Method)
4XESTACKTRACE          at java.net.SocketInputStream.read(SocketInputStream.java(Compiled Code))
4XESTACKTRACE          at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
4XESTACKTRACE          at oracle.net.ns.Packet.receive(Unknown Source)
4XESTACKTRACE          at oracle.net.ns.DataPacket.receive(Unknown Source)
4XESTACKTRACE          at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)
4XESTACKTRACE          at oracle.net.ns.NetInputStream.read(Unknown Source)
4XESTACKTRACE          at oracle.net.ns.NetInputStream.read(Unknown Source)
4XESTACKTRACE          at oracle.net.ano.AnoComm.g(AnoComm(Compiled Code))
4XESTACKTRACE          at oracle.net.ano.AnoComm.readUB4(AnoComm(Compiled Code))
4XESTACKTRACE          at oracle.net.ano.Ano.g(Ano(Compiled Code))
4XESTACKTRACE          at oracle.net.ano.Ano.negotiation(Ano(Compiled Code))
4XESTACKTRACE          at oracle.net.ns.NSProtocol.connect(Unknown Source)
4XESTACKTRACE          at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java(Compiled Code))
4XESTACKTRACE          at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java(Compiled Code))
4XESTACKTRACE          at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java(Compiled Code))
4XESTACKTRACE          at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java(Compiled Code))
4XESTACKTRACE          at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java(Compiled Code))
4XESTACKTRACE          at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java(Compiled Code))
4XESTACKTRACE          at java.sql.DriverManager.a(Unknown Source)
4XESTACKTRACE          at java.sql.DriverManager.getConnection(Unknown Source) 락 획득자
4XESTACKTRACE          at test.frame.j2ee.SCDataSourceProxy.getJDBCConnection(SCDataSourceProxy.java(Compiled Code))
4XESTACKTRACE          at test.frame.j2ee.SCEjbBean.getJDBCConnection(SCEjbBean.java(Compiled Code))
                                                      .
                                                      .
4XESTACKTRACE          at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java(Compiled Code))
3XHNATIVESTACK       Native Stack
NULL                 ------------
3XHSTACKLINE         at 0xD022C688 in recv
3XHSTACKLINE         at 0xD4B79838 in NET_Recv
3XHSTACKLINE         at 0xD4B89EA4 in Java_java_net_SocketInputStream_socketRead0

4.getconnection이 synchronized처리 돼 있음에 수상함을 느껴, 제니퍼에서 제공하는 메모리내 클래스가 어떤 jar에 의해 로드 돼 있는지 확인을 함.

5.DriverManager class가 제니퍼 Agent의 lwst.jdk.jar에 있는 DrvierManager로 변경 돼 있음을 확인하고 디컴파일 해 getconnection이 synchronized처리 돼 있음 을 확인함.

조치

lwst.jdk.jar에 있는 DriverManger class를 제거하고 해당 APPL을 재기동 해 성능 지연을 해결함.

AS-IS

TO-BE

결과 모니터링

APPL 개선 가이드

APPL 성능 개선을 하고 DB를 모니터링 하다 보니, DB의 SYS가 올라가는 것을 확인함. 원인은 Connection Pool을 사용하지 않다보니, 매번 Connection을 맺다 보니 OS의 SYS가 올라가는 것을 확인해 최종적으로는 Connection Pool을 사용하게 해 해당 이슈를 모두 해결 했음.