Sun Developer Network 공식 블로그 :: dbx 를 이용해서 JVM 레벨의 hang 디버깅 하기

썬 스튜디오 dbx 툴을 이용해서 솔라리스 x86 시스템에서 특히 고통스러운 JVM hang 을 디버그 하는 방법을 설명합니다.

순서

솔라리스에서 JVM의 crash 나 hang 같은 이슈를 트러블슈팅 하기 위해서 필자는 보통 썬 스튜디오 dbx 툴을 이용합니다. 대부분의 경우 저희들은 JVM 의 제품 빌드에 의해 성성된 core 파일을 고객으로 부터 받습니다. JVM 의 제품 빌드는 어떠한 디버깅 정보도 포함하고 있지 않기 때문에 dbx 는 JVM 오브젝트의 상세정보를 보여줄 수 없고 이것이 디버깅과 주소 해석을 매우 어렵게 합니다.

해결 방법

dbx 디버거는 프로세스가 실행되는데 사용되었던 공유 오브젝트 대신에 다른 오브젝트를 '로드' 하고 '사용' 할 수 있는 매우 유용한 기능을 제공합니다.

(dbx) loadobject -load alternate-lib

(dbx) loadobject -use alternate-lib

이 기능은 프로세스들을 디버깅 하거나 아무런 디버깅 정보도 없는 코어 파일을 분석할때 매우 유용합니다. 디버깅 하려고 하는 라이브러리를 -g 플래그로 컴파일 한다음 이것을 dbx 디버깅 세션에서 로드할 수 있습니다.

JVM hang 디버깅

이 글에 상황에서 고객은 솔라리스 x86 시스템의 JDK 버전 1.5.0_08 에서 매우 심각한 hang 을 겪었고 프로세스가 kill -3 에 조차도 반응하지 않았었습니다. 고객은 저희들에게 hang 이 걸린 프로세스의 코어 파일을 보내 왔습니다.

dbx 가 디버깅 정보를 가지도록 하기 위해 저희들은 JDK 버전 1.5.0_08 의 libjvm.so 을 -g 플래그를 이용해서 재빌드 하였고 이것을 로드해서 dbx 가 해당 .so 파일을 사용하도록 하였습니다. 이러한 변경으로 인해 dbx 는 어떠한 디버깅 정보도 가지고 있지 않았던 libjvm.so 파일에 의해 생성된 코어 파일로 부터 모든 디버깅 정보를 얻을 수 있었습니다.

코어파일의 pstack 결과는 VMThread 가 Threads_lock 을 얻으려고 시도하고 있고 메인 쓰레드는 Threads_lock 조건을 기다리고 있고 다른 쓰레드 3992 또한 Threads_lock 을 잡으려고 기다리고 있음을 보여 줍니다. 그러므로 이 락이 데드락을 유발하고 있다고 보여 집니다. 코어 파일의 내용은 다음과 같습니다.

-----------------  lwp# 1 / thread# 1  --------------------
 fef4009b lwp_park (0, 0, 0)
 fef3a909 cond_wait_queue (807c540, 807c528, 0, 0) + 3b
 fef3ae02 _cond_wait (807c540, 807c528) + 66
 fef3ae44 cond_wait (807c540, 807c528) + 21
 fe92fc64 __1cHMonitorEwait6Mil_i_ (807c4d0, 0, 0) + 2a4
 fecf526b __1cHThreadsKdestroy_vm6F_i_ (8073fb9, 0, 806dc14, fee4d33c, fee4a2a0, 10004) + 7b
 feb66ea3 jni_DestroyJavaVM (fee43560) + 123
 08051f8e main     (2, 807017c, 80432b4) + bfb
 080512fa ???????? (86, 8043468, 804346d, 8043494, 80434a8, 80434c6)
-----------------  lwp# 11 / thread# 11  --------------------
 fef4009b lwp_park (0, 0, 0)
 fef399bb slow_lock (fbc92000, 807c528, 0) + 3d
 fef39ab1 mutex_lock_impl (807c528, 0) + ec
 fef39bbd mutex_lock (807c528) + 1a
 fe8c9a00 __1cFMutexElock6MpnGThread__v_ (807c4d0, 8261480) + c0
 fe8cc1fe __1cFMutexElock6M_v_ (807c4d0) + 4e
 fe996295 __1cUSafepointSynchronizeFbegin6F_v_ (fee493fc, 8261480, fedee000, f8199b74, 3, f8199bbc) + 85
 fea659c4 __1cIVMThreadEloop6M_v_ (8261480) + 134
 fea66478 __1cIVMThreadDrun6M_v_ (8261480) + 88
 fecbe0f2 __1cG_start6Fpv_0_ (8261480) + d2
 fef3fd52 _thr_setup (fbc92000) + 4e
 fef40040 _lwp_start (fbc92000, 0, 0, f8199ff8, fef40040, fbc92000)
-----------------  lwp# 3992 / thread# 3992  --------------------
 fef4009b lwp_park (0, 0, 0)
 fef399bb slow_lock (6c173c00, 807c528, 0) + 3d
 fef39ab1 mutex_lock_impl (807c528, 0) + ec
 fef39bbd mutex_lock (807c528) + 1a
 fe8ea95e __1cFMutexbClock_without_safepoint_check6M_v_ (807c4d0) + 7e
 fe95c56e __1cUSafepointSynchronizeFblock6FpnKJavaThread__v_ (a27f780) + ee
 fecb6825 __1cGParkerEpark6Mix_v_ (a27f908, 0, d964b198, 45) + 1e5
 fed0963d Unsafe_Park (a27f840, 6807aba4, 0, d964b198, 45, 9480bcb8) + 1dd
 f876f2f9 ???????? (0, 0, a27c330, 0, 9ae69a8, 0)
 00000000 ???????? (fecf6330, fea09d40, fea03c80, fe964f40, fe91cc40, fe939c50)
 00000000 ???????? (fffffd2c, 3badd9be, f468fe16, e78b7254, fe1dbbcc, 0)
 00000000 ???????? ()

이제 Threads_lock 을 dbx 를 이용해서 살펴 보겠습니다.

(dbx) print -fx Threads_lock
Threads_lock = 0x807c4d0

(dbx) print -r *((Monitor*)0x807c4d0)
*((class Monitor *) 0x807c4d0) = {
    Monitor::Mutex::_lock_count      = 0
    Monitor::Mutex::_lock_event      = 0x807c500
    Monitor::Mutex::_suppress_signal = 0
    Monitor::Mutex::_owner           = 0x97b0978   <----------------
    Monitor::Mutex::_name            = 0xfed97a0f "Threads_lock"
    Monitor::Mutex::INVALID_THREAD   = 0
    Monitor::_event   = (nil)
    Monitor::_counter = 0
    Monitor::_waiters = 1
    Monitor::_tickets = 0
}

(dbx) print -r *((Thread*)0x97b0978)
*((class Thread *) 0x97b0978) = {
    Thread::ThreadShadow::_pending_exception = (nil)
    Thread::_exception_file                       = (nil)
    Thread::_exception_line                       = 0
    Thread::_real_malloc_address                  = 0x97b0d28
    Thread::_rawmonitor_list                      = (nil)
    Thread::_SR_lock                              = 0x9b7b890
    Thread::_vm_suspend_depth                     = 0
    Thread::_suspend_flags                        = 0
    Thread::_active_handles                       = 0x97b0b48
    Thread::_free_handle_block                    = (nil)
    Thread::_last_handle_mark                     = 0x65c92618
    Thread::_oops_do_parity                       = 0
    Thread::_highest_lock                         = 0x65c92cb8 "x^I{^I\xe8^K{^I\xb0\xd6\x82\xf4\xa0H\xbeu"
    Thread::_unboosted_priority                   = NoPriority
    Thread::_tlab                                 = {
        Thread::ThreadLocalAllocBuffer::_start               = 0x762476d8
        Thread::ThreadLocalAllocBuffer::_top                 = 0x7624c750
        Thread::ThreadLocalAllocBuffer::_end                 = 0x76257308
        Thread::ThreadLocalAllocBuffer::_size                = 14078U
        Thread::ThreadLocalAllocBuffer::_refill_waste_limit  = 219U
        Thread::ThreadLocalAllocBuffer::_number_of_refills   = 6U
        Thread::ThreadLocalAllocBuffer::_fast_refill_waste   = 0
        Thread::ThreadLocalAllocBuffer::_slow_refill_waste   = 202U
        Thread::ThreadLocalAllocBuffer::_gc_waste            = 0
        Thread::ThreadLocalAllocBuffer::_slow_allocations    = 0
        Thread::ThreadLocalAllocBuffer::_allocation_fraction = {
            Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_average      = 0.006992618
            Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_sample_count = 1U
            Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_weight       = 35U
            Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_last_sample  = 0.006992618
        }
        Thread::ThreadLocalAllocBuffer::_target_refills      = 50
        Thread::ThreadLocalAllocBuffer::_global_stats        = 136222936
    }
    Thread::_vm_operation_started_count           = 1
    Thread::_vm_operation_completed_count         = 1
    Thread::_current_pending_monitor              = (nil)
    Thread::_current_pending_monitor_is_from_java = 1
    Thread::_current_waiting_monitor              = (nil)
    Thread::_osthread                             = 0x97b0b00     <-------------
    Thread::_resource_area                        = 0x8c55f50
    Thread::_handle_area                          = 0x98dafc0
    Thread::_stack_base                           = 0x65c93000 ""
    Thread::_stack_size                           = 262144U
    Thread::_self_raw_id                          = 1731617792U
}

(dbx) print -r *((OSThread*)0x97b0b00)
*((class OSThread *) 0x97b0b00) = {
    OSThread::_start_proc                   = (nil)
    OSThread::_start_parm                   = (nil)
    OSThread::_state                        = RUNNABLE
    OSThread::_interrupted                  = 0
    OSThread::_thread_id                    = 11982U
    OSThread::_lwp_id                       = 11982U
    OSThread::_caller_sigmask               = {
        OSThread::__sigbits = (4U, 0, 0, 0)
    }
    OSThread::_vm_created_thread            = 1
    OSThread::_current_callback             = (nil)
    OSThread::_current_callback_lock        = (nil)
    OSThread::_interrupt_event              = 0x97b07d8
    OSThread::_saved_interrupt_thread_state = _thread_new
}

이전의 결과는 Threads_lock 의 소유자가 쓰레드 ID 11982 임을 보여 줍니다. 이제 이 쓰레드의 스텍 트레이스를 살펴 보겠습니다.

(dbx) thread t@11982
t@11982 (l@11982) stopped in __lwp_park at 0xfef4009b
0xfef4009b: __lwp_park+0x000b:  jae      __lwp_park+0x19        [ 0xfef400a9, .+0xe ]
(dbx) where
current thread: t@11982
=>[1] __lwp_park(0x0, 0x0), at 0xfef4009b
  [2] mutex_lock_queue(0x67366400, 0x0, 0x88a0598, 0x0), at 0xfef3911f
  [3] slow_lock(0x67366400, 0x88a0598, 0x0), at 0xfef399bb
  [4] mutex_lock_impl(0x88a0598, 0x0), at 0xfef39ab1
  [5] __mutex_lock(0x88a0598), at 0xfef39bbd
  [6] Mutex::wait_for_lock_blocking_implementation(0xa27f908, 0x97b0978), at 0xfe9d93ba
  [7] Mutex::lock(0xa27f908, 0x97b0978), at 0xfe8c99ea
  [8] Mutex::lock(0xa27f908), at 0xfe8cc1fe
  [9] Parker::unpark(0xa27f908), at 0xfecb69bb
  [10] os::interrupt(0xa27f780), at 0xfecbf6bb
  [11] Thread::interrupt(0xa27f780), at 0xfecf2ed9
  [12] JVM_Interrupt(0x97b0a38, 0x65c923fc, 0x65c923d0, 0x0, 0x65c923fc, 0xf4873020, 0x0, 0xf482f600, 0x65c923fc, 0x65c92424,
 0xf8202b6b, 0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400, 0xf482db6b, 0x65c92438, 0xf4873020), at 0xfeb92255
  [13] 0xf820843a(0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400), at 0xf820843a
  [14] 0xf8202b6b(0x0, 0x0, 0x97f59c18, 0x9593fdc0, 0x65c9243c, 0xf5746e95), at 0xf8202b6b
  [15] 0xf8202b6b(0x967a0c40, 0x9, 0x968f6eb8, 0x65c92464, 0xf57472be, 0x65c92498), at 0xf8202b6b
  [16] 0xf8202b6b(0x0, 0x968f6eb8, 0x967a0c40, 0x65c9249c, 0xf5845a0c, 0x65c924c4), at 0xf8202b6b
  [17] 0xf8202b6b(0x1b58, 0x967a0c40, 0x65c924c8, 0xf5845674, 0x65c92524, 0xf58a1f78), at 0xf8202b6b
  [18] 0xf8202b6b(0x7624c168, 0x7624c138, 0x7624c108, 0x7624c0d8, 0x7624bee8, 0x7624bd00), at 0xf8202b6b

쓰레드가 모니터 0xa27f908 을 얻으려고 시도하고 있습니다.

이제 모니터를 살펴 보겠습니다.

(dbx) print -r *((Monitor*)0xa27f908)
*((class Monitor *) 0xa27f908) = {
    Monitor::Mutex::_lock_count      = 0
    Monitor::Mutex::_lock_event      = 0x88a0570  <-----------
    Monitor::Mutex::_suppress_signal = 0
    Monitor::Mutex::_owner           = (nil)
    Monitor::Mutex::_name            = 0xfed97c99 "Park Semaphore"
    Monitor::Mutex::INVALID_THREAD   = 0
    Monitor::_event   = (nil)
    Monitor::_counter = 0
    Monitor::_waiters = 0
    Monitor::_tickets = 0
}
(dbx) print -r *((Event*)0x88a0570)
More than one identifier 'Event'.
Select one of the following:
 0) Cancel
 1) class os::Solaris::Event
 2) class Solaris::Event
> 1
*((class os::Solaris::Event *) 0x88a0570) = {
    Event::_count   = 0
    Event::_nParked = 0
    Event::CachePad = (-6.7529205832009e-205, -6.6220952168053e-205, -1.2786650622506e-204, -1.9668306807887e-204)
    Event::_mutex   = (
    {
        Event::_lwp_mutex::flags = {
            Event::_lwp_mutex::flag1        = 4U
            Event::_lwp_mutex::flag2        = '\0'
            Event::_lwp_mutex::ceiling      = '\0'
            Event::_lwp_mutex::mbcp_type_un = {
                Event::_lwp_mutex::bcptype      = 0
                Event::_lwp_mutex::mtype_rcount = {
                    Event::_lwp_mutex::count_type1 = '\0'
                    Event::_lwp_mutex::count_type2 = '\0'
                }
            }
            Event::_lwp_mutex::magic        = 19800U
        }
        Event::_lwp_mutex::lock  = {
            Event::_lwp_mutex::lock64  = {
                Event::_lwp_mutex::pad = ""
            }
            Event::_lwp_mutex::lock32  = {
                Event::_lwp_mutex::ownerpid = 0
                Event::_lwp_mutex::lockword = 16842752U
            }
            Event::_lwp_mutex::owner64 = 72339069014638592ULL
        }
        Event::_lwp_mutex::data  = 1813462016ULL
    }

)
    Event::_cond    = (
    {
        Event::_lwp_cond::flags = {
            Event::_lwp_cond::flag  = ""
            Event::_lwp_cond::type  = 0
            Event::_lwp_cond::magic = 17238U
        }
        Event::_lwp_cond::data  = 0
    }

)
    Event::FreeNext = (nil)
    Event::Immortal = 0
}

여기서 _lwp_mutex->data, 0x6C173C00 는 ulwp_t) 의 소유자입니다.

다음으로 이 쓰레드를 살펴 보겠습니다.

(dbx) x 0x6C173C00/30X
0x6c173c00:      0x6c173c00 0x00000000 0x00000000 0x00000000
0x6c173c10:      0x00000000 0x00000000 0x00000000 0x00000000
0x6c173c20:      0x00000000 0x00000000 0x00000000 0xfef6b740
0x6c173c30:      0x00000000 0x00000000 0x6c174000 0x6c173800
0x6c173c40:      0x00000000 0x00000000 0x00000000 0x6803b000
0x6c173c50:      0x00040000 0x00000000 0x6807b000 0x00040000
0x6c173c60:      0x6803b000 0x00040000 0x00000000 0x00000398
0x6c173c70:      0x00000f98 0x0000007f

쓰레드 0x00000f98 (쓰레드 ID 3992) 는 이 Event::mutex 를 잡고 있는 쓰레드 ID 입니다.

이제 쓰레드 3992를 살펴 보겠습니다.

(dbx) thread t@3992
t@3992 (l@3992) stopped in __lwp_park at 0xfef4009b
0xfef4009b: __lwp_park+0x000b:  jae      __lwp_park+0x19        [ 0xfef400a9, .+0xe ]
(dbx) where
current thread: t@3992
=>[1] __lwp_park(0x0, 0x0), at 0xfef4009b
  [2] mutex_lock_queue(0x6c173c00, 0x0, 0x807c528, 0x0), at 0xfef3911f
  [3] slow_lock(0x6c173c00, 0x807c528, 0x0), at 0xfef399bb
  [4] mutex_lock_impl(0x807c528, 0x0), at 0xfef39ab1
  [5] __mutex_lock(0x807c528), at 0xfef39bbd
  [6] Mutex::lock_without_safepoint_check(0x807c4d0), at 0xfe8ea95e
  [7] SafepointSynchronize::block(0xa27f780), at 0xfe95c56e
  [8] Parker::park(0xa27f908, 0x0, 0xd964b198, 0x45), at 0xfecb6825
  [9] Unsafe_Park(0xa27f840, 0x6807aba4, 0x0, 0xd964b198, 0x45, 0x9480bcb8), at 0xfed0963d

이 쓰레드는 락 Threads_lock 을 기다리고 있습니다.

그러므로 쓰레드 11982 와 3992 는 데드락을 가지고 있습니다:

쓰레드 11982 는 Thread_lock 를 가지고 있고 모니터 0xa27f908 를 기다리고 있음.
3992 는 0xa27f908 에 락을 가지고 있고 Threads_lock 을 얻으려고 하고 있음.

이 문제는 자바 SE 5.0 업데이트 15 와 자바 SE 6의 CR 6601725 에서 수정되었습니다.

저자에 관하여

Poonam Bajaj 는 2001년 부터 썬의 자바 유지 그룹에서 일하고 있습니다. 이 그룹은 고객이 자바 관련 제품들과 관련하여 제기한 이슈를 처리하고 업데이트를 배포하는 일을 담당합니다. Poonam 은 문제 해결을 좋아 하고 특히 전문 분야는 Hotspot VM 입니다.

이 글의 영문 원본은
Debugging a JVM Level Hang Using dbx
에서 보실 수 있습니다.

"개발자코너" 카테고리의 다른 글

솔라리스상에서 PHP 를 이용한 웹 어플리케이션 작성 (댓글 0개 / 트랙백 0개) 2008/07/17
솔라리스 SPARC 플랫폼, x86 플랫폼 간의 컴파일러 차이점 (댓글 28개 / 트랙백 3개) 2007/09/17
쉘 프로그래밍 기법 (댓글 1개 / 트랙백 0개) 2005/09/23
Solaris OS, SPARC Platform Edition에서 x86 Platfo... (댓글 1개 / 트랙백 0개) 2005/10/23
libumem 라이브러리를 이용하여 어플리케이션 내의 메모리 관리 버그를 잡아 내는 방법 (댓글 1개 / 트랙백 1개) 2006/03/23
스토리지 유틸리티 실습: ZFS 스냅샷과 Amazon S3 연동 (댓글 0개 / 트랙백 1개) 2008/04/17
썬 스튜디오: VIS 명령을 사용하여 중요한 루틴의 속도를 향상시키기 (댓글 1개 / 트랙백 0개) 2006/02/23
병렬 프로그래밍 단어 총정리 (댓글 22개 / 트랙백 3개) 2007/09/17
병렬 컴퓨팅을 위한 어플리케이션 개발 (댓글 0개 / 트랙백 2개) 2007/12/14
DTrace를 사용하여 유저가 조정하는 애플리케이션 크래쉬 데이타 정보 모으기 (댓글 1개 / 트랙백 0개) 2006/08/23

Sun Developer Network 공식 블로그

dbx 를 이용해서 JVM 레벨의 hang 디버깅 하기

"개발자코너" 카테고리의 다른 글

TRACKBACK :: http://blog.sdnkorea.com/blog/trackback/571

댓글을 달아 주세요

카테고리

검색

달력

통계

태그목록

최근에 올라온 글

최근에 달린 댓글

최근에 받은 트랙백

링크