|
안녕하세요 ? 이번에는 이전 포스트에 이어 Thread dump로 분석할 수 있는 경우인 Hang 상태와 CPU 과부하 원인 분석에 대해 설명드리도록 하겠습니다.
지난 포스트에는 java에서의 주요 Hang 현상이 locking에 대해 내부 메카니즘과 사례를 통해 알아 보았습니다.
이번에는 응답지연으로 인해 Hang이 발생한 것 처럼 보이는 경우에 대해 알아 보도록 하겠습니다.
응답 지연이 발생할 경우도 thread dump를 통해 어느 부분에서 지연이 발생하는지 stacktrace 확인을 통해 가능합니다.
이때 주의해야 할 점은 이미 이전의 포스트에서 설명드렸던 부분인데요. thread dump를 한번만 수행해서는 정확한 원인을 알 수 없다는 것입니다.
꼭 53원칙으로 thread dump를 수행하여 각 thread들에 대한 stack이 변화 사항을 확인하여야 정확한 분석이 가능합니다.
53원칙은 제가 이전의 포스트에서 5초 간격으로 최소 3번이상 thread dump를 수행하라는 의미에서 만든 thread dump수행 원칙입니다.
위의 사례는 thread들이 모두 지연되어 thread dump를 수행한 결과 모두가 socket read상태에서 지연 중임을 알 수 있었습니다.
특정 jsp가 수행되면서 처리 시 실제 업무 비즈니스 로직 처리를 위해 HTTP 통신을 통해 다른 서버로 요청을 전송하고 결과값을 받는 시스템입니다.
이 경우는 해당 시스템의 문제가 있는 것이 아니라 상대방 시스템의 처리 지연으로 같이 지연이 발생한 경우입니다.
이러한 경우도 thread dump를 통한 stacktrace를 통해 어느 부분에서 지연이 발생하는지를 상세하게 분석할 수 있습니다.
그러나 위에서의 예에서도 각 클래스와 메소드들이 어떤 역할을 하는지 어느정도 파악하고 있어야 문제의 원인을 알 수 있는 것입니다.
각 업무 담당자와 시스템 운영자와의 면담과 협업은 필수입니다.
다음으로는 CPU자원을 폭식하는 녀석을 찾기 위해 thread dump를 활용하는 방법에 대해 알아 보도록 하겠습니다.
CPU 자원을 폭식하는 녀석을 찾기 위해서는 OS 툴을 통한 모니터링이 사전에 이루어져야 하는데요.
이 부분은 이전의 포스트를 통해 이미 한번 알아보았던 부분입니다.
간단히 각 OS 별로 CPU 자원을 모니터링하는 방법에 대해 다시 한번 알아보고 사례를 통해 실제 현장에서 분석하는 방법에 대해 설명드리도록 하겠습니다.
CPU 자원을 모니터링하고 문제의 부분을 찾기 위해서는 프로세스단위 및 쓰레드 단위의 CPU 자원 모니터링이 필요합니다.
각 OS 별로 이러한 기능을 제공하는 툴이 있으며 이를 잘 활용하면 CPU 자원 모니터링 뿐 아니라 다양한 정보를 모니터링 할 수 있습니다.
각 OS 별로 다음과 같은 명령어를 통해 프로세스 및 쓰레드에 대한 CPU 모니터링을 할 수 있습니다.
이제 각 OS 별로 CPU 자원을 모니터링하여 문제점을 확인하고 원인을 분석하는 방법에 대해 사례를 통해 설명드리도록 하겠습니다.
먼저, Solaris에서 CPU 자원을 폭식하는 녀석을 찾는 방법입니다.
Solaris에서는 CPU 자원 모니터링을 위해 prstat 명령어를 이용합니다.
다음과 같은 명령을 사용하여 thread별 CPU를 많이 사용하는 thread를 확인할 수 있습니다.
# prstat -L -m -p [프로세스ID] [Interval]
다음은 prstat 명령을 통한 CPU 과부하 thread와 thread dump상의 thread를 찾는 방법입니다.
위와 같이 prstat을 통해 프로세스의 thread단위로 CPU 사용율을 모니터링하여 CPU를 많이 차지하는 thread를 확인하고 thread dump를 수행하여 해당 thread를 lwpid와 nid로 매칭(16진수 변환 필요)하여 찾을 수 있습니다.
그럼 해당 thread가 어떠한 작업을 수행중이며 왜 CPU를 많이 차지하는지 분석할 수 있습니다.
다음은 HP-UX에서 CPU 자원을 폭식하는 녀석을 찾는 방법입니다.
HP-UX에서는 CPU 자원 모니터링을 위해 Glance를 이용합니다.
Glance에서 전체 CPU 사용율을 확인하고 이에 따라 각 프로세스별 CPU 사용율을 확인합니다.
Glance를 수행했을때 첫번째 화면에서 특별히 설정을 하지 않는한 CPU 사용율을 기준으로 정렬된 프로세스 리스트들이 출력됩니다.
그럼 그 중 CPU 자원이 높은 프로세스에 대해 상세 모니터링을 수행하는데요. 여기서 필요한 스킬이 CPU 자원이 높다고 어떻게 판단하느냐 입니다.
다양한 방법이 있겠지만 보통 CPU 자원이 지속적으로 높을 수도 있지만 주기적으로 또는 불규칙적으로 높을 수도 있습니다.
지속적이거나 주기적으로 높다면 손쉽게 파악이 되겠지만 불규칙적으로 높을 경우는 advisor 모드를 이용하여 별도로 모니터링 정보를 로깅하여 분석하는 것이 용이합니다.
이러한 advisor 모드에 대한 부분은 "Glance advisor을 통한 CPU 자원 모니터링 방법(http://blog.naver.com/bumsukoh/110107086979)" 부분을 참고하시기 바랍니다.
여기서는 지속적이거나 주기적으로 높은 프로세스가 파악되었다면 "s"를 입력하여 해당 프로세스의 ID를 입력합니다.
그러면 프로세스에 대한 상세 정보화면으로 변경되며 여기서 다시 각 thread별로 CPU 자원 사용율을 확인하기 위해 "G"를 입력하면 각 thread별 각종 자원 사용율 정보가 출력됩니다.
화면에서 CPU Util, CPU 누적 시간등을 확인하여 CPU 자원을 많이 차지하는 thread 녀석을 찾아 내는 것입니다.
이렇게 해당 thread를 찾았다면 해당 TID를 생성한 thread dump 정보에서 해당 thread를 찾아 stack을 확인하면 CPU 자원을 차지하는 원인을 파악할 수 있습니다.
위와 같이 Glance를 통해 CPU 자원을 많이 사용하는 thread를 확인하고 thread dump에서 해당 TID를 이용하여 thread를 찾아 stack을 확인함으로써 원인을 파악합니다.
그럼 마지막으로 AIX에서 CPU를 폭식하는 녀석을 찾는 방법입니다.
AIX에서는 ps 명령어를 통해 프로세스의 thread에 대한 CPU 자원 사용율을 모니터링 할 수 있습니다.
아무래도 위의 Solaris와 HP-UX에 비해서는 모니터링 방법에서 조금 뒤떨어집니다.
하지만 ps 명령어도 다음과 같은 명령어를 통해 상당히 효과적인 모니터링이 가능합니다.
# ps -mp [프로세스ID] -o THREAD
다음 그림은 AIX에서 ps 명령어를 통한 CPU 과부하 thread와 javacore에서 해당 thread를 찾는 방법입니다.
위와 같이 ps -mp 명령어를 통해 프로세스의 thread단위로 CPU 사용율을 모니터링하여 CPU를 많이 차지하는 thread를 확인하고 javacore를 생성하여 해당 thread를 TID와 native ID로 매칭(16진수 변환 필요)하여 찾을 수 있습니다.
그럼 해당 thread가 어떠한 작업을 수행중이며 왜 CPU를 많이 차지하는지 분석할 수 있습니다.
이제 마지막으로 실제 분석한 사례를 통해 CPU를 많이 차지하는 thread와 원인을 파악하는 방법에 대해 설명드리겠습니다.
다음 사례는 Solaris에서 Hahstable의 정보를 읽어 올때 부적절한 방법으로 인해 CPU 과부하가 발생한 경우입니다.
위와 같이 prstat을 통해 모니터링한 결과 특정 thread들이 CPU를 많이 차지하는 것을 알 수 있었습니다.
특이한 점은 CPU를 많이 차지하는 thread들의 LWPID가 계속 바뀌는 것입니다.
그렇다면 CPU를 많이 차지하는 로직을 thread들이 수행하고 있다는 의심을 하였으며, 이러한 로직을 확인하기 위해 thread dump를 지속적으로 수행하여 해당 threa들의 stack을 확인하였습니다.(물론 이럴 경우 Java profiling을 수행하면 가장 확실하게 확인 할 수 있습니다. 다음에 Java profile에 대한 설명드리도록 하겠습니다.)
thread들의 stack을 확인해 보니 공통적으로 ClassStore.get() 메소드가 많이 걸려있는 것이 확인되었으며, 해당 로직들에 대한 분석에 들어갔습니다.
분석을 수행해 보니 해당 Rule 패키지내에서 관련 데이터를 Hashtable에 저장하고 저장한 Hashtable을 읽어들어 하나씩 if 문을 이용하여 확인하는 로직이였습니다.
이러한 if 로직이 전체 코드의 2/5 정도를 차지하고 있는 것이 확인되었습니다.
문제는 이러한 if 로직들이 Hashtable내의 데이터를 확인하기 위해 아래와 같은 비효율적인 구문을 사용하고 있었습니다.
========================================
Hashtable aaa = .....
Object value = null;
if(aaa.containsKey("zzz")) --> 비효율적인 구문
value = aaa.get("zzz"); --> 비효율적인 구문
else
return null;
========================================
위의 로직은 Hashtable의 내용을 두번씩 검색하게 되어 불필요한 CPU 자원을 사용하는 경우입니다.
이 경우 아래와 같이 변경하여 수행한 결과 CPU 자원이1/3 줄어든 것을 확인 할 수 있었습니다.
========================================
Hashtable aaa = .....
Object value = null;
return aaa.get("zzz");
========================================
다음 사례는 AIX에서 Thread의 looping 로직으로 인해 CPU 과부하 현상이 발생한 경우입니다.
우선 위와 같이 ps -mp 명령어를 사용하여 모니터링하여 실제 CPU를 많이 차지하는 thread를 확인 후 shell의 while을 이용하여 해당 프로세스의 thread에 대한 CPU 사용율을 상세히 모니터링 하여 CPU의 과부하를 확인후 javacore에서 해당 thread의 수행 내역을 확인합니다.
위의 사례는 CPU 사용율 영역 중 System(Kernel)영역이 높은 경우였습니다.
해당 thread의 stack 확인 결과 SQLLoader라는 thread의 Watcher가 지속적으로 수행하고 있는 것이 확인 되었으며, 해당 thread는 SQL문이 별도로 저장된 파일의 변경 여부를 확인하여 메모리에 갱신하는 로직이였습니다.
문제는 변경 여부를 확인하는 주기를 설정하지 않아 sleep없이 계속 looping을 수행하며 파일의 변경 여부를 확인하는 것입니다.
이러다 보니 아무런 사용자 요청이 없어도 항상 System CPU를 30%이상 차지하고 있었습니다.
위의 사례들에서와 같이 thread dump는 여러가지로 활용도가 많은 분석 도구입니다.
thread dump를 통해 해당 시점에 무슨일을 하고 있는지를 stack을 통해 확인할 수 있다는 것은 개발자나 운영자, 저와 같은 트러블슈팅 담당자에게도 굉장히 유용한 도구입니다.
이것으로 Java 트러블슈팅의 첫번째 섹션인 thread dump 분석 부분을 마치도록 하겠습니다.
나름대로 저가 가지고 있는 지식과 경험을 토대로 포스트를 기록해 보았습니다. 이러한 내용들이 개발자, 운영자 분들이 참고할 만한 내용이 되었으면 합니다.
다음 포스트 부터는 Java 트러블슈팅 두번째 섹션인 GC Log 분석 부분을 시작하도록 하겠습니다.
즐거운 나날 되시고, 인생은 언제나 Never Stop Exploring !!!
|
