태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

[ Enterprise Java는 거대한 동기화 머신이다 - Thread ] Enterprise Java & Oracle 성능 분석의 기초 - Part4

Enterprise Java 2007.08.28 11:15
Enterprise Java는 거대한 동기화 머신이다.

Sun HotSpot JVM이 사실상의 업계 표준 JVM이지만, 항상 최고의 최적화를 제공하지는 않는다. 개인적인 생각으로는 Sun/HP에서는 Sun HotSpot JVM이, IBM AIX에서는 IBM JVM이, Windows/Linux(x86)에서는 BEA JRockit JVM이 최적의 성능을 낼 것으로 기대한다.

IBM JVM과 JRockit JVM은 Sun이 제정한 JVM 표준을 따르되, 자신들만의 최적화 기법을 통해서 또 다른 뛰어난 성능을 제공한다. 따라서 현재 시스템에서 테스트를 통해 최적의 성능을 지닌 JVM을 취사 선택할 필요가 있다.

블로그 Part3에서 Sun HotSpot JVM에서 Thread 동기화에 의한 블로킹이 Thread Dump에서 어떻게 관찰되는지 살펴본 보았는데, 이제 동일한 현상이 IBM JVM과 JRockit JVM에서는 어떻게 관찰되는지 살펴 보자.

IBM JVM
IBM JVM의 Thread Dump는 Sun HotSpot JVM에 비해서 매우 풍부한 정보를 제공한다. 단순히 Thread들의 현재 상태뿐 아니라, JVM의 상태에 대한 여러 가지 정보를 제공한다. 이러한 다양한 정보들은 JVM의 정확한 상태를 이해하는데 큰 도움이 된다.

Case1: Synchronized에 의한 동기화
아래 내용이 "synchronized" 문장에 의한 Thread 블로킹이 발생한 상황의 Thread Dump의 일부분이다.
-------------------------------------------------------------------------------------------
// 모니터 정보
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
...
2LKMONINUSE sys_mon_t:0x3003C158 infl_mon_t: 0x00000000:
3LKMONOBJECT java.lang.Object@30127640/30127648: Flat locked by thread ident 0x08, entry count 1 //<-- 특정 오브젝트가 0x08 Thread에 의해 Locking
3LKNOTIFYQ Waiting to be notified: // <-- 세 개의 Thread가 대기 중
3LKWAITNOTIFY "Thread-1" (0x356716A0)
3LKWAITNOTIFY "Thread-2" (0x356F8020)
3LKWAITNOTIFY "Thread-3" (0x3577FA20)
...
// Java Object Monitor 정보
1LKOBJMONDUMP Java Object Monitor Dump (flat & inflated object-monitors):
...
2LKFLATLOCKED java.lang.Object@30127640/30127648
3LKFLATDETAILS locknflags 00080000 Flat locked by thread ident 0x08, entry count 1
...
// Thread 목록
1LKFLATMONDUMP Thread identifiers (as used in flat monitors):
2LKFLATMON ident 0x02 "Thread-4" (0x3000D2A0) ee 0x3000D080
2LKFLATMON ident 0x0B "Thread-3" (0x3577FA20) ee 0x3577F800
2LKFLATMON ident 0x0A "Thread-2" (0x356F8020) ee 0x356F7E00
2LKFLATMON ident 0x09 "Thread-1" (0x356716A0) ee 0x35671480
2LKFLATMON ident 0x08 "Thread-0" (0x355E71A0) ee 0x355E6F80
// <--
java.lang.Object@30127640/30127648을 점유하고 있는 0x03 Thread의 이름이 Thread-0 임을 알 수 있다
...
// Threrad Stack Dump
2XMFULLTHDDUMP Full thread dump Classic VM (J2RE 1.4.2 IBM AIX build ca142-20050929a (SR3), native threads):
3XMTHREADINFO "Thread-4" (TID:0x300CB530, sys_thread_t:0x3000D2A0, state:CW, native ID:0x1) prio=5 // <-- Thread-4는 CW(Conditional Waiting)상태
3XHNATIVESTACK Native Stack
NULL ------------
3XHSTACKLINE at 0xDB84E184 in xeRunJavaVarArgMethod
...

3XMTHREADINFO "Thread-3" (TID:0x300CB588, sys_thread_t:0x3577FA20, state:CW, native ID:0xA0B) prio=5
4XESTACKTRACE at Thread1.run(dump_test.java:21)
...
3XMTHREADINFO "Thread-2" (TID:0x300CB5E8, sys_thread_t:0x356F8020, state:CW, native ID:0x90A) prio=5
4XESTACKTRACE at Thread1.run(dump_test.java:21)
...
3XMTHREADINFO "Thread-1" (TID:0x300CB648, sys_thread_t:0x356716A0, state:CW, native ID:0x809) prio=5
4XESTACKTRACE at Thread1.run(dump_test.java:21)
...
3XMTHREADINFO "Thread-0" (TID:0x300CB6A8, sys_thread_t:0x355E71A0, state:R, native ID:0x708) prio=5 // <-- Thread-0(ident=0x08) Thread는 Runnable(Running) 상태. 락 홀더에 해당
4XESTACKTRACE at Thread2.run(dump_test.java(Compiled Code))
3XHNATIVESTACK Native Stack
NULL ------------
3XHSTACKLINE at 0x344DE720 in
...

위의 결과를 블로그 Part3에서 설명한 Sun HotSpot JVM의 Thread Dump 결과와 비교해보면, 정보의 양이 훨씬 많고 체계적인 것을 알 수 있다.

위의 결과를 해석하면 "Thread-0(ident=0x08)" Thread가 java.lang.Object@30127640/30127648 오브젝트에 대해 Monitor 락을 점유하고 실행(state:R) 중이며, 나머지 세 개의 Thread "Thread 1,2,3"은 동일 오브젝트에 대해 락을 획득하기 위해 대기(Conditional Waiting)상태이다.

Case2: Wait/Nofity에 의한 동기화
Wait/Nofity에 의한 동기화에 의해 Thread 블로킹이 발생하는 경우에는 한가지 사실을 제외하고는 Case1과 완전히 동일하다.

앞서 블로그 Part3에서 언급한 것처럼, Wait/Notify에 의한 동기화의 경우 실제로 락을 점유하고 있는 Thread는 존재하지 않고, Nofity해주기를 대기할 뿐이다. 따라서 락을 점유하고 있는 Thread가 어떤 Thread인지에 대한 정보가 Thread Dump에 나타나지 않는다.(실제로 락을 점유하고 있지 않기 때문에)
따라서 정확한 블로킹 관계를 해석하려면 좀더 면밀한 분석이 필요하다.

아래 내용은 Wait/Notify에 의한 Thread 동기화가 발생하는 상황의 Thread Dump의 일부이다. Case1과의 차이점에 주의하자. Wait/Notify에 의한 Thread 동기화의 경우에는 락을 점유하고 있는 Thread의 정체를 바로 알 수 없다.(블로킹이 아닌 단순 대기이기 때문에)
...
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
...
2LKMONINUSE sys_mon_t:0x3003C158 infl_mon_t: 0x3003BAC0:
3LKMONOBJECT java.lang.Object@30138C58/30138C60:
// <-- Object에 대해 Waiting Thread가 존재하지만 Locking 되어 있지는 않다!!!
// <-- Case1과 잘 비교해서 차이를 이해하자!!!
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "Thread-3" (0x3577F5A0)
3LKWAITNOTIFY "Thread-1" (0x355E7C20)
3LKWAITNOTIFY "Thread-2" (0x356F7A20)
...

BEA JRockit
비록 Sun HotSpot JVM이나 IBM JVM 만큼 많이 사용되지는 않지만 JVM의 삼두 마차 중 하나라고 할 수 있다. 특히 IBM의 Websphere와 함께 시장을 양분하고 있는 WAS인 Weblogic을 만든 BEA에서 만든 JVM이라는 면에서 주목할만 한다. JRockit JVM은 x85 아키텍처에 최적화된 JVM으로 Windows나 Linux 플랫폼에서는 최적의 성능을 내게끔 구현되었다. 따라서 기회가 된다면 성능 테스트를 통해 사용을 검토해보기 바란다.

JRockit의 Thread Dump는 두 경쟁 JVM과 비교하면 가장 깔끔하고 예쁜 결과를 보고한다. 그 이유는 아래 예를 보면 금방 알 수 있다.

Case1: Synchronized에 의한 동기화
아래 Thread Dump를 보면 Thread간의 블로킹 관계가 매우 깔끔하고 명확하게 기술되어 있음을 알 수 있다.
===== FULL THREAD DUMP ===============
Sun Aug 26 01:10:42 2007
BEA JRockit(R) R26.4.0-63_CR302700-72606-1.5.0_06-20061127-1108-win-ia32

...
// Thread-0이 java/lang/Object@0x1073DF58 락을 점유하고 있음을 알 수 있다.
"Thread-0" id=9 idx=0x16 tid=3488 prio=5 alive
at Thread2.run()V(dump_test.java:36)
^-- Holding lock: java/lang/Object@0x1073DF58[thin lock]
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

// Thread1,2,3은 java/lang/Object@0x1073DF58 락을 대기하고 있으며, Blocked 상태이다.
"Thread-1" id=10 idx=0x18 tid=3264 prio=5 alive, in native, blocked
-- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock]
at jrockit/vm/Threads.sleep(I)V(Native Method)
at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source)
at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source)
at Thread1.run()V(dump_test.java:21)
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

"Thread-2" id=11 idx=0x1a tid=3580 prio=5 alive, in native, blocked
-- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock]
at jrockit/vm/Threads.sleep(I)V(Native Method)
at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source)
at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source)
at Thread1.run()V(dump_test.java:21)
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

"Thread-3" id=12 idx=0x1c tid=3068 prio=5 alive, in native, blocked
-- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock]
at jrockit/vm/Threads.sleep(I)V(Native Method)
at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source)
at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source)
at Thread1.run()V(dump_test.java:21)
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

// 가장 유용한 것은 아래의 Lock Chain 정보이다.Thread 간의 Lock Chaining 정보를 직관적으로 파악할 수 있도록 해준다.
Blocked lock chains

===================
Chain 2:
"Thread-2" id=11 idx=0x1a tid=3580 waiting for java/lang/Object@0x1073DF58 held by:
"Thread-0" id=9 idx=0x16 tid=3488 in chain 1

Chain 3:
"Thread-3" id=12 idx=0x1c tid=3068 waiting for java/lang/Object@0x1073DF58 held by:
"Thread-0" id=9 idx=0x16 tid=3488 in chain 1

Open lock chains
================
Chain 1:
"Thread-1" id=10 idx=0x18 tid=3264 waiting for java/lang/Object@0x1073DF58 held by:
"Thread-0" id=9 idx=0x16 tid=3488 (active)

===== END OF THREAD DUMP ===============

Case2: Wait/Nofity에 의한 동기화
Wait/Notify에 의한 동기화가 발생하는 경우에는 블로킹이 발생한 것이 아니라 단순 대기 상태이기 때문에 Thread 간의 블로킹 관계가 명확하게 드러나지 않는다.

아래 예를 보면 Thread1,2,3은 같은 락(java/lang/Object@0x1073DF58)에 대한 Notify를 대기하고 있다는 것을 쉽게 알 수 있지만 락 점유자(는 없기 때문에)의 정보는 알 수 없다. 이것은 어떤 JVM을 막론하고 동일한 현상이다.
...
"Thread-0" id=9 idx=0x16 tid=2200 prio=5 alive
at Thread2.run()V(dump_test2.java:36)
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

"Thread-1" id=10 idx=0x18 tid=1784 prio=5 alive, in native, waiting
-- Waiting for notification on: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/Threads.waitForSignal(J)Z(Native Method)
at jrockit/vm/Locks.wait(Ljava/lang/Object;J)V(Unknown Source)
at java/lang/Object.wait()V(Native Method)
at Thread1.run()V(dump_test2.java:23)
^-- Lock released while waiting: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

"Thread-2" id=11 idx=0x1a tid=2904 prio=5 alive, in native, waiting
-- Waiting for notification on: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/Threads.waitForSignal(J)Z(Native Method)
at jrockit/vm/Locks.wait(Ljava/lang/Object;J)V(Unknown Source)
at java/lang/Object.wait()V(Native Method)
at Thread1.run()V(dump_test2.java:23)
^-- Lock released while waiting: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace

"Thread-3" id=12 idx=0x1c tid=3708 prio=5 alive, in native, waiting
-- Waiting for notification on: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/Threads.waitForSignal(J)Z(Native Method)
at jrockit/vm/Locks.wait(Ljava/lang/Object;J)V(Unknown Source)
at java/lang/Object.wait()V(Native Method)
at Thread1.run()V(dump_test2.java:23)
^-- Lock released while waiting: java/lang/Object@0x1073DF58[fat lock]
at jrockit/vm/RNI.c2java(IIII)V(Native Method)
-- end of trace


Thread Dump를 통한 Thread 동기화 문제 해결의 실사례
아래 Thread Dump은 실제 운영 환경에서 성능 문제가 발생한 경우에 추출한 것이다. Thread Dump를 분석한 결과 많은 수의 Worker Thread들이 다음과 같이 블로킹되어 있었다.
...

"http8080-Processor2" daemon prio=5 tid=0x042977b0 nid=0x9a6c in Object.wait() [503f000..503fdb8]
at java.lang.Object.wait(Native Method)
- waiting on <0x17c3ca68> (a org.apache.commons.pool.impl.GenericObjectPool)
at java.lang.Object.wait(Object.java:429)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(Unknown Source)
- locked <0x17c3ca68> (a org.apache.commons.pool.impl.GenericObjectPool)
at org.apache.commons.dbcp.PoolingDriver.connect(PoolingDriver.java:146)
at java.sql.DriverManager.getConnection(DriverManager.java:512)
- locked <0x507dbb58> (a java.lang.Class)
at java.sql.DriverManager.getConnection(DriverManager.java:193)
- locked <0x507dbb58> (a java.lang.Class)
at org.jsn.jdf.db.commons.pool.DBManager.getConnection(DBManager.java:40)
at org.apache.jsp.managerInfo_jsp._jspService(managerInfo_jsp.java:71)
...
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:534)

"http8080-Processor1" daemon prio=5 tid=0x043a4120 nid=0x76f8 waiting for monitor entry [4fff000..4fffdb8]
at java.sql.DriverManager.getConnection(DriverManager.java:187)
- waiting to lock <0x507dbb58> (a java.lang.Class)
at org.jsn.jdf.db.commons.pool.DBManager.getConnection(DBManager.java:40)
at org.apache.jsp.loginOK_jsp._jspService(loginOK_jsp.java:130)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:137)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:210)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:295)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:241)
...
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:534)
...

위의 Thread Dump를 분석해보면 다음과 같은 사실을 알 수 있다.
  • java.sql.DriverManager.getConnection() 내부에서 Connection을 얻는 과정에서 Synchronized에 의한 Thread 블로킹이 발생
  • org.apache.commons.pool.impl.GenericObjectPool.borrowObject() 내부에서 Connection을 얻는 과정에서 Wait/Notify에 의한 Thread 블로킹이 발생

즉, Connection Pool에서 Connection을 얻는 과정에서 Thread 경합이 발생하고 있다. 이는 현재 Connection Pool의 완전히 소진되었고 이로 인해 새로운 DB Request에 대해 새로운 Connection을 맺는 과정에서 성능 저하 현상이 생겼다는 것을 의미한다. 만일 Connection Pool의 최대 Connection 수가 낮게 설정되어 있다면 대기 현상은 더욱 심해질 것이다. 다른 Thread가 DB Request를 끝내고 Connection을 놓을 때까지 기다려야 하기 때문이다.

해결책은? Connection Pool의 초기 Connection 수와 최대 Connection수를 키운다. 만일 실제 발생하는 DB Request수는 작은데 Connection Pool이 금방 소진된다면 Connection을 닫지 않는 문제일 가능성이 크다. 이 경우에는 소스 검증이나 모니터링 툴을 통해 Connection을 열고 닫는 로직이 정상적으로 작동하는지 검증해야 한다.

(참고) 다행히 iBatisHibernate같은 프레임웍들이 보편적으로 사용되면서 JDBC Connection을 잘못 다루는 문제는 거의 없어지고 있다. 개발자의 실수를 미연에 방지해준다는 의미에서 매우 바람직한 현상이라고 할 수 있다.

--------------------------------------------------------------------------------------------------

다음 글에 계속...

신고
tags : ,
Trackback 0 : Comment 1
  1. Stargazer 2012.12.22 13:37 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment

티스토리 툴바