Dtrace와 Java : Java를 Dtrace로 해부해볼 수 있을까?

어려운 문제다.
Dtrace를 만든 3명중에 한명인 Adam 조차도 Java를 dtrace로 완전히 분해하는 게
어렵다고 했다. 그나마 JDK 1.6이후에는 솔라리스10의 jvm이 dtrace probe를 지원하게
되서 훨씬 쉬어지긴 했지만 말이다.

JDK 1.6.x이전에는 java vm은 운영체제 입장에서 독립적인 프로세스이면서, 내부적으로는 자바 애플리케이션을 실행시켜주는 머신 역할을 하고 있어서, 실제로 jvm의 애플리케이션인 java의 thread들은 운영체제에서 정확하게 무슨일을 하는지 알 수가 없었다.  그래서, jvm을 블랙박스라고 했다.

안에  어떤일이 일어나는 지 모르는 상태에서 jvm의 그 자체에 대고 dtrace 때려봐야 코끼리 뒷다리 만지기식이었다고 할까.

그래서, JDK 1.4.x와 JDK 1.5.x에서는 jvm이 구동될때 dtrace로 추적이 가능하도록 하는 플러그인 모듈(JNI 인터페이스)이 오픈 소스 프로젝트로 개발되었는데 성능이 워낙  후지다 보니, 욕을 많이 먹는 와중에 jdk 1.6.x이 발표되면 흐지 부지 되었다.

기술적으로는 운영체제에서는 jvm 안에 있는 thread의 움직임을 알수가 없으므로 jvm이 내부의 움직임을 외부 운영체제에 알려주어야만 운영체제에서는 무언가를 해볼 수가 있다. 그나마, 솔라리스8에서 솔10이 되면서 Thread-to-LWP 할당 방식이 1-to-1이 되었기 때문에 Java Thread를 운영체제에서 어느 정도 알게 된것이 발전이라면 발전이다. (참고 pstack, jstack)

JDK 1.5이전에는 java vm이 dtrace에게 java application에 대한 정보를 제공해주기 위해서 java vm이 제공하는 JNI기반의 DVMTI라는 trace interface module을 통하여 dtrace를  지원했었다. (https://solaris10-dtrace-vm-agents.dev.java.net/ )

그러나, 이 모듈은 매우 심각한 오버헤드로 많은 자바 개발자들로 하여금 경악을 금치 못하게함으로써 많은 사용이 되지 않았으며, 그러는 동안에 jdk 1.6 버젼에서 외부 trace를 위한 기능이 대폭적으로 개선되면서, 솔라리스용 java vm 1.6.x는 특별히 자체적으로(natively) dtrace를 지원하도록 개선되었다.

쉽게 얘기하면, jdk 1.6대를 사용해서 무언가를 돌리고 있으면, 애플리케이션은 자동적으로 java vm의 hotspot vm의 dtrace probe(검사 포인트)를 실시간 등록을 해준다. 때문에, java vm 로딩은 다소 좀 늦어지긴 했으나, 모니터링 부분에서는 혁신적인 발전이 제공되었다고 볼 수 있다.

아울러 jdk 1.6이 제공하는 trace 확장 기능은 java vm 자체의 모니터링 및 trace 기능도 발전시켜서 아주 화려한 툴들을(jconsole, demo/JTop, demo/MemoryManagement) 기본적으로 제공함에 따라 dtrace의 필요성이 많이 감소해졌다. ㅡ.ㅡ;

그러나, 여전히 dtrace는 막강하다. 애플리케이션의 문제를 논리적으로 접근하는 힘은 어디에서나 강할뿐 아니라, jdk 1.6이 java thread의 procedure에 대한 정보를 모두 노출함으로써 dtrace적 논리로 문제의 근원을 찾아볼 수 있게 되었다.

freemind라는 java application을 jdk 1.6으로 실행했을 경우이다.
bash-3.00# pgrep freemind
2352
bash-3.00# ptree 2352
2352  /bin/bash /usr/sfw/bin/freemind.sh ; freemind를 실행시켜 주는 쉘이다.
  2356  /usr/bin/java -Dfreemind.base.dir=/usr/sfw/lib/freemind-bin-max-0.8.0/ ; 실제 freemind.jar의 java pid
bash-3.00# dtrace -l | grep 2356 | c++filt | tail
62071 hotspot_jni2356        libjvm.so jni_UnregisterNatives UnregisterNatives-entry
62072 hotspot_jni2356        libjvm.so jni_UnregisterNatives UnregisterNatives-return
62073 hs_private2356         libjvm.so void VM_CMS_Initial_Mark_Operation::doit() cms-initmark-begin
62074 hs_private2356         libjvm.so void VM_CMS_Initial_Mark_Operation::doit() cms-initmark-end
62075 hs_private2356         libjvm.so void VM_CMS_Final_Remark_Operation::doit() cms-remark-begin
62076 hs_private2356         libjvm.so void VM_CMS_Final_Remark_Operation::doit() cms-remark-end
62077 hs_private2356         libjvm.so HashtableEntry*Hashtable::new_entry(unsigned,oopDesc*) hashtable-new_entry
62078 hs_private2356         libjvm.so void RuntimeService::record_safepoint_begin() safepoint-begin
62079 hs_private2356         libjvm.so void RuntimeService::record_safepoint_end() safepoint-end
62356 hotspot_jni2925        libjvm.so jni_GetCharArrayRegion GetCharArrayRegion-return

(  c++filt는 Sunstudio를 설치해야만 제공되는 C++ name demangle 유틸이다./opt/SUNWspro/bin에 있다.  )

java가 pid 2356의 dtrace probe를 위한 probe point를 대거 등록해놓은 것이 보인다.
이중에서 hotspot_jni2356으로 등록되어 있는 probe statement가 중요하다. 실제 자바 애플리케이션의 함수들을 trace할때 필요하다.

그러면, freemind라는 java application을 dtrace할 수 있게 되었다. dtrace 해주자. ;-)
#dtrace -n 'hotspot_jni2925:::{@[probefunc]=count()}' ; pid 2925가 가장 일을 많이 하는 함수를 프린트하자.
...
  jni_IsAssignableFrom                                           1984
  jni_GetSuperclass                                              2388
  jni_IsInstanceOf                                               3818
  jni_SetIntArrayRegion                                         27688
  jni_GetByteArrayElements                                      28064
  jni_MonitorEnter                                              28064
  jni_MonitorExit                                               28064
  jni_ReleaseByteArrayElements                                  28064
  jni_GetArrayLength                                            36036
  jni_GetPrimitiveArrayCritical                                 38248
  jni_ReleasePrimitiveArrayCritical                             38248
  jni_CallStaticVoidMethod                                      69000

이렇게 나온다. 햐! 엄청 좋아졌다.
그러면, 가장 많은 부하를 제공하고 있는 jni_CallStaticVoidMethod()가 호출되는 어떤 경우일까? 또 dtrace해주자 !

#dtrace -n 'hotspot_jni2925::jni_CallStaticVoidMethod:CallStaticVoidMethod-entry{@[jstack()]=count()}'
몇가지 경우가 나타났다.

...
              libjvm.so`jni_CallStaticVoidMethod+0xe0
              libmawt.so`X11SD_Lock+0x43
              libawt.so`Java_sun_java2d_loops_MaskFill_MaskFill+0x96
              sun/java2d/loops/MaskFill.MaskFill(Lsun/java2d/SunGraphics2D;Lsun/java2d/SurfaceData;Ljava/awt/Composite;IIII[BII)V*
              sun/java2d/pipe/AlphaColorPipe.renderPathTile(Ljava/lang/Object;[BIIIIII)V*
              sun/java2d/pipe/DuctusShapeRenderer.renderPath(Lsun/java2d/SunGraphics2D;Ljava/awt/Shape;Ljava/awt/BasicStroke;)V*
              sun/java2d/pipe/DuctusShapeRenderer.fill(Lsun/java2d/SunGraphics2D;Ljava/awt/Shape;)V*
              sun/java2d/pipe/PixelToShapeConverter.fillRect(Lsun/java2d/SunGraphics2D;IIII)V*
              sun/java2d/S
              0xfc6a5f35
              0xfc402e9d
              0xfc6dc99d
              0xfc402e9d
              0xfc402e9d
              0xfc758abc
              0xfc76f8fa
              0xfc402c71
              0xfc402c71
              0xfc6947fe
              0xfc782015
              0xfc75cc9c
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc768b95
              0xfc699bb4
              0xfc5cd0d0
              0xfc402c71
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc400202
              libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
              libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
              libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_+0xc1
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_+0x7e
              libjvm.so`__1cMthread_entry6FpnKJavaThread_pnGThread__v_+0xd2
              libjvm.so`__1cKJavaThreadRthread_main_inner6M_v_+0x4c
              libjvm.so`__1cKJavaThreadDrun6M_v_+0x196
              libjvm.so`java_start+0xd3
              libc.so.1`_thr_setup+0x52
              libc.so.1`_lwp_start
             1006

              libjvm.so`jni_CallStaticVoidMethod+0xe0
              libmawt.so`X11SD_Unlock+0x1d4
              libawt.so`Java_sun_java2d_loops_MaskFill_MaskFill+0x20c
              sun/java2d/loops/MaskFill.MaskFill(Lsun/java2d/SunGraphics2D;Lsun/java2d/SurfaceData;Ljava/awt/Composite;IIII[BII)V*
              sun/java2d/pipe/AlphaColorPipe.renderPathTile(Ljava/lang/Object;[BIIIIII)V*
              sun/java2d/pipe/DuctusShapeRenderer.renderPath(Lsun/java2d/SunGraphics2D;Ljava/awt/Shape;Ljava/awt/BasicStroke;)V*
              sun/java2d/pipe/DuctusShapeRenderer.fill(Lsun/java2d/SunGraphics2D;Ljava/awt/Shape;)V*
              sun/java2d/pipe/PixelToShapeConverter.fillRect(Lsun/java2d/SunGraphics2D;IIII)V*
              sun/java2d/S
              0xfc6a5f35
              0xfc402e9d
              0xfc6dc99d
              0xfc402e9d
              0xfc402e9d
              0xfc758abc
              0xfc76f8fa
              0xfc402c71
              0xfc402c71
              0xfc6947fe
              0xfc782015
              0xfc75cc9c
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc768b95
              0xfc699bb4
              0xfc5cd0d0
              0xfc402c71
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc402e9d
              0xfc400202
              libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
              libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
              libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_+0xc1
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_+0x7e
              libjvm.so`__1cMthread_entry6FpnKJavaThread_pnGThread__v_+0xd2
              libjvm.so`__1cKJavaThreadRthread_main_inner6M_v_+0x4c
              libjvm.so`__1cKJavaThreadDrun6M_v_+0x196
              libjvm.so`java_start+0xd3
              libc.so.1`_thr_setup+0x52
              libc.so.1`_lwp_start
             1010

그 중에 가장 호출 빈도수가 높은 경우는 위와 같다. (c++filt를 쓰지 않아서 mangling 되어있다)
자바가 화면에 새로 그리기 위해서 호출이 많은 것 같다(필자는 자바 전문가가 아니라서 자세히 설명하진 못하겠다. 하지만, 애플리케이션 그래픽 프로그램이고 이벤트를 받지 않으면 별로 하는 일이 없기 때문에 이렇게 나오는게 아닌가 싶다.)

mangling이 답답하다면 demangle 해서 보자.

자바를 아는 자바 전문가들에게는 진짜 필요한 툴이 아닌가 싶다.
참고로, dtrace는 솔라리스10에서만 사용가능하므로, 솔라리스에서만 이렇게 dtrace를 통한 java trace가 가능하다.

문제를 알았다면, 이제 자바 전문가를 불러서 해결해달라고 하자. ㅡ.ㅡ;