너무 좋은 글들... 최근 dump 분석 때문에 골머리 썩고 있었는데 완전 딱 맞는 자료를 발견했다...
http://blog.naver.com/bumsukoh/110114008655
이번 포스트에서는 Thread dump를 분석하기 전에 Thread들에 대한 정보를 확인하기 위한 유용한 OS 툴들에 대한 내용을 다루어 보겠습니다.
각 OS별로 프로세스 및 Thread 레벨로 상태를 확인하기 위한 명령어들을 제공합니다. 멀티 Thread 기반으로 운영체제들이 변해가면서 제공하는 기능들이 생겨나게 되었습니다.
여기서 설명드리는 OS 툴들은 모두 프로세스에 대한 Native Stack 정보를 출력하는 것입니다.
물론 java stack을 볼 수 없지만 문제가 발생한 Thread에 대한 Native Stack 및 Thread ID를 확인할 수 있습니다. 일부 Java Thread dump에서는 Native Thread ID를 통해 해당 Thread를 찾기도 합니다.
첫번째로 Solaris에서 제공하는 명령어에 대해 알아 보겠습니다.
Solaris에서 가장 유용하게 사용할 수 있는 프로세스와 Thread 모니터링 툴로는 prstat 이 있습니다.
prstat은 생각보다 굉장히 강력한 기능을 가지고 있습니다. 프로세스와 Thread의 CPU 자원 사용율 및 메모리 사용율을 알 수 있지만, CPU 사용율에 대한 microstat 정보를 확인 할 수 있어 굉장히 유용합니다.
저의 경우 이 prstat의 microstat정보를 유용하게 활용하여 시스템의 CPU 자원 사용의 문제점을 확인하고 디버깅한 경험이 있습니다.
prstat 명령어 사용법은 다음과 같습니다.
# prstat -L -m -p [프로세스 ID] [refresh interval]
옵션은 다음과 같습니다.
- "-L" 은 Thread 레벨의 정보를 출력합니다.
- "-m" 은 microstat 정보를 출력합니다.
- "-p" 은 모니터링할 프로세스 ID입니다.
- "refresh interval" 은 모니터링 정보 갱신 주기입니다.
다음은 prstat 출력 결과 예입니다.
==============================================================================================
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
----------------------------------------------------------------------------------------
24565 mspbpp 0.8 0.1 0.0 0.0 0.0 0.0 99 0.2 198 1 198 0 java/14
24565 mspbpp 0.8 0.1 0.0 0.0 0.0 0.0 99 0.2 198 1 198 0 java/19
24565 mspbpp 0.4 0.1 0.0 0.0 0.0 0.0 99 0.2 198 0 198 0 java/15
24565 mspbpp 0.4 0.1 0.0 0.0 0.0 0.0 99 0.2 198 0 198 0 java/21
24565 mspbpp 0.4 0.1 0.0 0.0 0.0 0.0 99 0.2 198 0 198 0 java/24
24565 mspbpp 0.1 0.0 0.0 0.0 0.0 100 0.0 0.0 2 0 3 0 java/2
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 39 0 39 0 java/8
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 2 0 4 0 java/9
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 java/13
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 java/12
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 java/11
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 java/10
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 100 0.0 0.0 0 0 0 0 java/7
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 100 0.0 0.0 0 0 0 0 java/6
24565 mspbpp 0.0 0.0 0.0 0.0 0.0 100 0.0 0.0 0 0 0 0 java/5
Total: 1 processes, 26 lwps, load averages: 0.15, 0.15, 0.14
==============================================================================================
위와 같이 프로세스의 Thread별(LWPID)로 CPU 사용에 대한 상세 정보가 출력됩니다.
다음은 prstat의 수행 결과 항목입니다. (여기서는 CPU에 대한 항목 만 설명합니다.)
| 구분 | 설명 |
| USER | The percentage of time the process has spent in user mode. |
| SYS | The percentage of time the process has spent in system mode. |
| LCK | The percentage of time the process has spent waiting for user locks. |
| SLP | The percentage of time the process has spent sleeping. |
| LAT | The percentage of time the process has spent waiting for CPU. |
이외 TRP, TFL, DFL, VCX, ICX, SCL, SIG 정보가 있습니다.
위의 결과 내용을 추출하여 분석한 결과 그래프(예시)를 살펴 보도록 하겠습니다.
이 그래프는 동일한 어플리케이션에 대해 사용자 수를 높이며 CPU 자원에 대한 사용 추이입니다.
눈여겨 볼 부분은 사용자가 많아 질 수록 SLP와 LCK 부분이 낮아 지며 LAT 부분이 높아 지는 것을 알 수 있습니다. 즉 사용자 량이 많아 처리량이 많아 질수록 초기에 LCK인 user locks (Java에서 object block이겠죠)과 SLP인 sleep (이 sleep도 대기상태입니다)이 높았다가 점점 낮아 집니다. 이는 Thread들이 일을 쉬지않고 열심히 더 하고 있다는 말이겠죠. 그러다 보니 LAT (CPU 할당 대기)가 점점 높아 지게 되는 것입니다.
여기에서 해당 시스템의 총 사용가능한 사용자에 대한 수치를 알 수 있습니다. 사실 이 작업을 할때는 패키지 제품에서 CPU 과부하가 있다는 것을 보여주기 위해 한것입니다. 결론적으로는 패키지의 CPU 과부하 버그를 조치한 경우입니다.
이렇게 prstat은 유용하게 사용할 수 있는 Solaris의 툴입니다.
그 다음으로는 pstack 명령어입니다.
pstack 명령어는 Solaris에서 프로세스의 Native Stack을 확인 할 수 있는 명령어입니다.(HP-UX에서도 사용합니다.)
이 pstack은 Native Stack (C 코드)만 확인 할 수 있습니다. java stack 에 대한 내용을 확인이 불가능하죠. 아예 나오지 않습니다. (Java 버전 1.5 이상에서는 pstack하고 유사한 jstack이라는 명령어가 제공됩니다. java stack을 Thread dump 없이 볼 수 있답니다.)
이러한 pstack은 JVM 내부의 흐름을 파악하기 위한 방법으로 유용하며, JVM의 Bug 같은 경우를 확인할 때 사용되기도 합니다.(사용되는 빈도는 극히 드물지만요..)
명령어 사용법은 다음과 같습니다.
# pstack [프로세스 ID]
출력 결과는 다음과 같습니다.
=============================================================================================
----------------- lwp# 25 / thread# 25 --------------------
ff2cc7f4 lwp_cond_wait (189b848, 189b830, 0, 0)
feb54b78 __1cCosNPlatformEventEpark6M_v_ (189b830, 45754, fed35879, 7c400, 189b800, fee069ec) + 108
fe5df09c __1cNObjectMonitorGEnterI6MpnGThread__v_ (323df0, 230c00, 323e00, fedb2000, 323e00, 1) + 1cc
fe53879c __1cNObjectMonitorFenter6MpnGThread__v_ (323df0, 230c00, 230c00, 2, 18a4678, 230e78) + 358
fec03c60 __1cSObjectSynchronizerKfast_enter6FnGHandle_pnJBasicLock_bpnGThread__v_ (ddbff834, ddbff908, 1, 230c00, 34800, d6a244) + a4
febad568 __1cNSharedRuntimebAcomplete_monitor_locking_C6FpnHoopDesc_pnJBasicLock_pnKJavaThread__v_ (ec450a70, ddbff908, 230c00, fede68e1, 6, fedb2000) + dc
fc055754 * weblogic/socket/SocketMuxer.readReadySocketOnce(Lweblogic/socket/MuxableSocket;Lweblogic/socket/SocketInfo;)Z+337 (line 1954)
fc63b53c * *weblogic/socket/DevPollSocketMuxer.processSockets()V [compiled] +12 (line 184)
fc005868 * weblogic/socket/SocketReaderRequest.run()V+3 (line 58)
fc005868 * weblogic/socket/SocketReaderRequest.execute(Lweblogic/kernel/ExecuteThread;)V+1 (line 84)
fc005d88 * weblogic/kernel/ExecuteThread.execute(Lweblogic/kernel/ExecuteRequest;)V+19 (line 288)
fc005868 * weblogic/kernel/ExecuteThread.run()V+32 (line 224)
fc00021c * StubRoutines (1)
fe561bdc __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (fc0001c0, 230c00, 1, d6a230, e11c6fd8, ddbffe78) + 208
fe90aebc __1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_ (ddbffe70, d6a234, fee07100, d6a240, ddbffda0, 230c00) + ec
fe5f0adc __1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_ (d6a234, ddbffe6c, ddbffe68, ddbffe64, ddbffe60, fee07100) + 6c
fe603350 __1cMthread_entry6FpnKJavaThread_pnGThread__v_ (dfc33688, 230c00, 54c00, fee07434, fee07100, fee06dd4) + 110
fec2318c __1cKJavaThreadRthread_main_inner6M_v_ (230c00, 16, fedee064, 19, fedb2000, 0) + 48
feb4ccbc java_start (230c00, 234e, fedb2000, fed33c51, 18a4678, fee02a2c) + 22c
ff2c8a20 _lwp_start (0, 0, 0, 0, 0, 0)
=============================================================================================
위와 같이 JVM을 구현한 Native Stack 입니다. Java 1.6 버전상의 Weblogic 10g에 대한 Thread Native Stack입니다.
lwp# 25 / thread# 25 는 Thread의 ID입니다. lwp는 Light Weight Process라 하여 경량의 프로세스라 하여 Thread에 대한 통칭입니다.
이 Thread ID는 이후에 설명드릴 Thread dump에서 thread와 매핑할 수 있는 key가 됩니다.
위의 Thread Stack에서는 Weblogic Executor Thread에서 사용자 요청을 받기 위해 대기중인 것을 알 수있습니다. 그래서 stack의 최종 frame은 "lwp_cond_wait (189b848, 189b830, 0, 0)" 입니다.
그 외에 프로세스 debug를 위한 dbx 나 Solaris의 막강 프로파일 툴인 Dtrace등을 활용할 수 있으나, 굉장히 advanced한 내용으로 많은 지식을 필요로 합니다.
대부분은 위의 내용정도만 아셔도 트러블슈팅하는데 많은 도움이 됩니다.
다음 포스트에서는 "OS 툴을 잘 활용하라 !" HP-UX 에 대해 설명드리도록 하겠습니다.
장마가 끝나니 날씨가 장난이 아니네요. 다시 장마시즌이 점점 그리워지는건 왜일까요 ^^
몸 건강들 하시고 다음 포스트에서 뵙겠습니다.
그럼 이만
'OS > Solaris' 카테고리의 다른 글
| 솔라리스 8에서 SunStudio 11 설치를 위한 jdk 설치 (0) | 2013.07.09 |
|---|---|
| Solaris_10 Hostname 변경 (0) | 2013.04.15 |
| 솔라리스 10에서 네트워크 설정하기. (1) | 2013.02.04 |
| 솔라리스 설치시 셋팅 사항 메모 (0) | 2013.02.04 |
| 프롬프트에 현재 디렉토리명을 넣으려면? (0) | 2011.12.22 |