모니터링 하는 거 하나 설치하려면 대부분 복잡합니다. 저는 이런 거 싫어서 그냥 JSP로 만들었습니다.(날코딩) 그냥 아래 threaddump.jsp를 다운받아 web app에 JSP 실행할 수 있는 디렉토리에 복사해 놓으면 됩니다. 참고로 Java 버전은 5 (JDK 1.5) 이상이어야 합니다.
0. 지혜롭게 살자
많은 개발자가 전통적(?)인 방법인 System.out....로 디버깅을 많이 하고 있다. 물론 이것처럼 확실한 방법도 없지만 eclipse나 다른 IDE의 디버그 기능을 이용하면 훨씬 빨리 문제를 찾을 수 있다.
특히 WAS에 배포된 환경에서 이런 방법으로 하려면 확인하기 위한 System.out...을 고칠 때마다 배포해야 하는데 이건 너무 고통스러운 작업이다.
단위 테스트시 에러가 발생했을 때는 eclipse등을 이용해서 디버깅하기가 수월하다.
그러나 WAS에 배포된 후에 에러가 발생했을 때는 약간의 작업이 필요하다. WAS를 eclipse에 embeded한 플러그인을 이용하는 방법도 있지만 WAS와 이클립스를 따로 띄워 원격으로 버그를 찾는 방법을 정리한다.
이럴 경우 서버환경에서 돌아가는 자바 코드의 문제점도 쉽게 잡을 수 있다. (물론 절대! 운영서버에서 하면 안되겠지만)
여기서는 tomcat 6와 eclipse 3.3 그리고 java6 환경을 가정하고 설명한다. (그 하위 버전도 방법은 동일하다)
1. 문제지점 찾기 WAS에서 애플리케이션을 배포하고 돌려보니 에러가 발생하고 아래와 같은 예외스택을 출력했다.
...
Using JRE_HOME: C:\java\jdk1.6.0_01
Listening for transport dt_socket at address: 8000
...
각 WAS에 -Xdebug ... 옵션을 설정하는 것은 조금씩 다르다. 각 WAS의 shell 스크립트를 살펴보고 적당한 환경변수를 주거나 직접 java 실행하는 부분에서 저 옵션을 추가하면 된다.
참고로 Maven 2로 개발할 경우 mvn jetty:run으로 WAS를 띄울 경우가 있는데 이런 경우는 다음과 같은 환경변수를 설정하고 띄우면 된다.
set MAVEN_OPTS= -Xdebug -Xnoagent -Xrunjdwp:transport=dt_socket,address=8000,server=y,suspend=n
3. JVM 디버깅 세션에 연결
이클립스에서 디버깅 세션을 열기 위해서는 다음 단계를 따라하면 된다. 물론 디버깅하기 위한 소스는 이클립스 프로젝트에 있다고 가정한다. 프로젝트를 선택한 상태에서 디버그를 시작하는 것을 있지 말라.
"Run > Open Debug Dialog..." 메뉴를 선택하면 아래와 같은 Debug 다이얼로그가 나타난다.
여기서 "Remote Java Application"을 선택하고 마우스 오른쪽 버튼을 클릭해 팝업 메뉴에서 "New"를 선택하면
위와 같이 새로운 디버그 연결을 위한 설정이 나타난다. 여기서 위와 같이 선택하고(Host와 Port는 변경할 수 있다. 위의 예에서 Port를 8000으로 설정했다.) "Debug 버튼"를 클릭한다.
그 후 "Debug" Perspective로 가면 (Window > Open Perspective를 통해 이동할 수 있음) 아래 그림과 같은 WAS의 쓰레드가 보이면 연결에 성공한 것이다.
3. Breakpoint 설정하기
이전 에러 스택을 통해 JDBCCredentialsSPI.java 소스의 32라인에서 무언가 null이라고 했다. 이 자바 소스를 열고 편집창 맨 앞에서 더블 클릭을 하거나 팝업 메뉴로 해당 라인에 breakpoint를 걸어두자.
4. 실행하고 상태 살펴보기(Inspect) 이제 에러가 난 부분을 실행하면 breakpoint에서 실행이 멈추고 대기할 것이다. 그럼 이제 어떤 부분이 null인지 살펴보자. Debug perspective에서 Variable 뷰에서 보면 rs는 nul로 나오지 않았다. 따라서 rs.getString(1) 부분이 null인지 살펴볼 것이다. 아래와 같이 rs.getString(1)을 선택하고 팝업메뉴로 "Inspect"를 선택한다.
그러면 위와 같이 현재의 rs.getStrng(1)을 평가하고 그 값을 보여준다. 이런 벌써 이 부분이 null인 것이 판명이 났다. 도대체 어떤 SQL을 실행했는데 첫번째 컬럼마저 null일까.
위의 소스에서 SQL 문장을 보려고 했다. 아 이것도 상수가 아니구나. 마찬가지 방법으로 inspect해서 SQL 문장을 확인한다. 소스 윗줄의 JDBCSPIEnv.getInstance().getAuthenticateSql()를 선택하여 살펴보았다. (팝업메뉴나 ctl+shift+i)
확인한 결과 실행한 SQL은 "select password from users where user_id = ?" 이고 넘어가는 파라메터는 "dykim"이었다.
DB의 테이블 내용을 살펴보니 dykim의 password 컬럼 값이 null 이었다.
아... rs.getString()이 null을 던질 수도 있는데... 단위 테스트하나 더 추가하고 고쳐야겠다.
개발 중 가끔 클래스를 수정해서 올렸는데 계속 적용이 되지 않는 경우가 있습니다. 그래서 계속 수정해서 올리고 변경이 안되어 쓸데없는 시간을 보내곤 합니다.
여기에서는 지금 구동 중인 java 클래스가 어디에서 로드되는지 알아내는 방법을 소개합니다.
사전지식
JVM의 Classloader 구조를 정확히 이해하고 클래스가 어디에서 어떻게 로드되어 구동되는지 알아야 합니다. 일반적으로 JVM의 클래스로더는 계층(hierarchy)구조를 가지고 있으며 각 클래스 로더는 하나의 부모 클래스 로더를 갖습니다. (물론 루트: boot classloader 제외)
다음은 Tomcat의 클래스로더 구조입니다. (WAS 마다 조금씩 다르지만 거의 비슷합니다.)
클래스 로더의 규칙은 다음과 같습니다.
클래스 로더는 동일한 클래스는 한번만 로드합니다.
동일한 이름(패키지 포함)을 가지고 동일한 클래스로더에서 로드된 클래스일 경우만 같은 클래스로 취급합니다. 클래스 이름을 가지더라도 서로 다른 클래스로더에서 로드될 경우 다른 클래스이며 이 경우 같은 클래스가 아니라는 에러를 발생합니다.
간혹 동일한 클래스(동일 패키지)인데도 클래스가 다르다는 이상한 에러를 만날 경우가 이런 경우입니다.
우선 자신의 클래스로더에서 클래스를 찾고 없으면 부모 클래스로더에서 찾습니다. 즉 클래스를 찾는 순서는 tomcat의 경우 클래스 로드 순서는 다음과 같습니다.
WebappX -> Shared -> Common -> System -> Bootstrap
예전에 Websphere에서 클래스를 찾는 순서를 반대로 (부모 클래스로더부터) 하는 설정이 있는 것을 보았습니다. 이건 일반적인 것은 아니고 해당 WAS에만 있는 특이한 경우입니다. 아직도 그 설정이 있는지 모르겠습니다. 5년도 더 된 것 같은데...
지금 동작중인 클래스 찾기
클래스를 수정해서 배포했는데 그 클래스가 적용되지 않는 경우 동일한 이름의 클래스가 여러 군데 있을 가능성이 높습니다. 즉 수정된 클래스는 상위 클래스로더에 계속 배포하고 테스트할 때는 다른 곳에(주로 자식클래스 로더) 이전의 클래스가 동작하여 헤매고 삽질하게 되는 경우가 있습니다.
다음 JSP 파일을 이용하여 쉽게 Web app에서 동작 중인 클래스를 찾아낼 수 있습니다.
원래 여러 가지 기능을 넣는라고 여러 유틸리티 클래스가 필요했는데 배포가 쉽도록 JSP안에 구겨넣었습니다.
WAR가 배포되는 위치에 이 jsp를 넣고 접근하면 Class Name을 입력하는 입력박스가 있습니다. 여기에 찾고자 하는 클래스 이름을 넣습니다. (예: oracle.jdbc.driver.OracleDriver)
위 그림이 그 결과입니다. Classloaders 항목에 클래스를 로드한 클래스 로더 정보가 나타납니다. 실제 클래스를 로드한 클래스 로더는 위의 경우 StandardClassLoader이고 그 아래는 그 부모 클래스 로더들입니다.
그리고 File Name을 보시면 실제 어떤 클래스 파일에서 로드했는지 보여줍니다. 위의 경우 oracle-10g_xe.jar 파일 안의 클래스를 로드 했네요.
그외 아래 정보는 WAS에 상관없이 JVM이 기본으로 로드하는 클래스 위치를 알려주는 정보입니다.
클래스패스 상의 리소스(텍스트파일, 이미지, ...)들을 찾는 방법도 유사합니다.
전형적인 예로 classpath에 걸린 log4j.properties를 아무리 수정해도 적용이 되지 않는 경우가 있습니다. 이 경우 다른 JAR 안이나 다른 위치에 log4j.properties가 있을 확률이 높습니다.
역시 다음 JSP 파일로 로드된 리소스와 동일한 이름의 리소스가 있는 위치들을 알려줍니다.
log4j.properties를 입력하고 엔터를 치며 위와 같이 리소스가 로드된 위치와 동일한 이름의 리소스들이 어디에 있는지 알아낼 수 있다.
리소스 이름은 클래스와 다르게 디렉토리를 "/"로 표현합니다. (예: kr/nextree/bcf/core/sqlmap/sqlmap-config.xml)
소스를 잘 보면 로드된 리소스의 내용을 출력하는 기능도 넣을 수 있겠죠...
정리
위 클래스 찾기와 리소스 찾기는 JSP 파일이 있는 webapp의 클래스로더에서 클래스와 리소스를 검색합니다. 따라서 상위 클래스로더에서 로드된 클래스가 참조하는 클래스에 문제가 생겼을 경우는 클래스로더 구조를 잘 파악하여 다른 방법으로 접근해야 할 수도 있습니다.
그러나 이 정도 방법으로도 대부분의 클래스 찾기와 관련된 문제를 해결할 수 있었습니다.
jQuery의 ajax API를 이용하여 웹애플리케이션을 구현하던 중 IE에서 이상한 현상을 발견하였습니다. jQuery의 ajax API 중 get 방식을 이용할 경우 IE에서 오직 한번만 서버를 호출합니다. 두번째 호출부터는 데이터가 바뀌어도 첫번째 정보를 주기에 갱신이 되지 않네요. 헐~
주로 불여우에서 개발하다가 나중에나 발견하는 현상인데 원인을 살펴보니 jQuery의 오류가 아니고 IE의 Caching 이슈이었습니다.
원인
Fire fox에서는 되고 IE에서는 안되니 IE에서 직접 XMLHTTP를 잡아서 호출해보았습니다.
아니나 다를까 fiddler로 잡아보니 서버 호출은 이루어지지 않고 4번째 줄 이벤트로 발생하지 않습니다. 구글링해보니 역시 IE의 caching 이슈가 있었습니다.
HTTP 는 대형 네트워크 시스템 아키텍처를 염두한 프로토콜이기에 단순하면서도 다양한 스펙들이 존재합니다. 대형 네트워크 시스템이다 보니 서로 주고 받는 정보가 많을 것이고 이에 네트워크 부하나 서버 부하가 발생할 소지가 매우 큽니다. 그런 상황을 위해 HTTP에는 단순하면서도 강력한 캐싱 메커니즘을 제공하고 있습니다.
브라우저와 웹서버와의 대화
브라우저는 웹서버에게 이미지, CSS 그리고 동적생성 정보(HTML, XML, JSON... 등 많은 컨텐츠를 요청합니다. 그런데 동일한 리소스(이하 컨텐츠)를 여러번 요청하는 경우가 굉장히 많습니다. 전형적인 예가 이미지나 CSS 같은 정적 컨텐츠인데 이런 것을 요청할 때 브라우저와 웹서버가 어떻게 대화하는지 아래 그림으로 살펴보겠습니다.
1: /AAA 컨텐츠를 주세요
2: OK 주었습니다. 이 컨텐츠의 마지막 갱신일은 2009년 9월 7일... 입니다. (컨텐츠 전송)
잠시 후...
3: /AAA 컨텐츠를 주세요. 아. 제가 캐시에 가지고 있는 건 마지막 갱신일이 2009년 9월 7일 ... 이네요
4: 변경사항 없습니다. 그냥 캐시에 있는 것 쓰세요. (아무것도 전송 안함)
브라우저 기본설정이라면 캐시에 있을 경우 브라우저가 시작하고 한 번 확인하고 두 번 다시는 GET 확인 요청을 하지 않습니다. 그냥 캐시에 있는 걸 씁니다. 브라우저를 다시 시작할 경우만 확인 요청을 합니다. 서버에 아예 요청도 안 가니 네트워크나 서버 부하는 무지 감소합니다. (IE 인터넷 옵션 설정에서 "페이지를 열 때마다"로 설정된 경우는 매번 확인 요청을 합니다.)
동적 컨텐츠와 304
서블릿이나 JSP 등으로 생성하는 동적 컨텐츠는 매번 정보가 갱신되어야 하기에 이런 메커니즘을 사용하지 않습니다. 그런데 간혹 서버 컨텐츠 마지막 갱신일을 알고 매우 요청이 많은 페이지 일 경우 위 메커니즘을 이용하는 것도 좋은 방법이겠네요. 다음 예는 JSP로 구현한 소스 예입니다.
비즈니스 로직이 실행되기 전 해당 정보 갱신일을 살펴보고 다시 줄 것인지 304를 던질 것인지 판단하는게 좋겠습니다. 그래야 필요없는 서버 로직이 수행되지 않습니다.
웹 애플리케이션 성능 향상
기본에 충실하는게 좋습니다. 우선은 문제가 되는 비즈니스 로직을 충분히 튜닝하십시오. 그런 후 특별한 캐싱 장치를 사용하거나 가능하면 위의 경우처럼 표준 캐싱 메키니즘을 충분히 활용하십시오.
그리고 비즈니스 로직의 성능을 높이기 위해 특정 비즈니스 로직을 열심히 튜닝하기 전에 우선 Fiddler 같은 도구로 브라우저와 서버가 무슨 통신을 하는지 살펴보는게 좋습니다. 생각보다 필요없는 요청이 많이 발생할 수도 있습니다.
느린 사이트는 우리를 참 짜증나게 합니다. 더 힘든 건 그 사이트를 내가 만들었을 때입니다. 튜닝을 할 건 다 했고 그래도 성능이 안 나오면 흥분하는 고객을 진정시키는 건 참 어려운 일입니다.
최후의 수단인 캐싱을 이용한 성능향상 방법을 소개합니다.
미리 만들어 놓기
극단적인 성능 향상 방법이라고해서 뭐 대단한 것은 아닙니다. 바로 캐싱하는 방법입니다. 우리는 알게 모르게 캐싱을 많이 사용하고 있습니다. DB도 그렇고 파일 시스템도 그렇고 웹서버도 사실 캐싱을 사용하고 있습니다. 반복적으로 사용하는 정보는 매번 만들지 않고 한번만 만들어 사용하자는 전략입니다.
웹 애플리케이션은 많은 경로를 지나고 그만큼 많은 캐싱 지점이 있습니다. 그림과 같은 단순한 아키텍처에서도 4개정도의 캐싱 가능한 지점이 있네요.
1번 지점에는 HTTP이 제공하는 막강한 캐싱 메커니즘이 있습니다. 바로 304이죠. 이 메커니즘은 한번 수정여부만 확인하고 아예 서버에 요청을 하지 않아 제일 효율이 좋은 방법입니다. HTTP 304 Not Modified 구현 방법 을 참조하세요.
2번 지점은 페이지 요청결과(HTML, XML, JSON, ..) 자체를 캐싱하는 기능입니다.
3번 지점은 서버쪽 연산결과를 메모리나 파일등에 넣고 계속 쓰는 것입니다. 대개 프로그래밍을 수반합니다.
4번 지점은 DB 질의 결과를 캐싱하는 것인데 iBatis나 Hibernate 같은 좋은 프레임워크들이 지원합니다.
캐싱지점이 브라우저와 가까울 수록 성능은 매우 뛰어난 반면 뒤로 갈수록 활용성이 좋아지는 장단점이 있습니다.
View 레이어 캐싱
표현계층이라고도 하는데 여기서는 OSCache로 서버 요청후 만들어진 결과(HTML, XML, JSON)를 통째로 캐싱하는 방법을 살펴봅니다. OSCache는 이를 위한 Servlet Filter를 제공합니다. 이를 이용한다면 웹 애플리케이션이 극단적으로 빨라지게 됩니다.
이와 같이 하면 한 번 캐싱된 페이지는 데이터가 바뀌어도 이전과 동일한 화면이 나올겁니다. 변경된 데이터를 화면에 반영하기 위해서는 캐시를 새로 적용해야합니다. 가장 간단한 방법은 cache를 삭제(flush)하는 겁니다. 물론 주기적으로 캐싱을 삭제하거나 삭제 정책을 추가하는 방법도 있습니다.
Cache를 flush하는 API를 제공합니다. 여기서는 그것을 이용하겠습니다.
1. CacheGroupsProvider
CacheFilter를 flush하기 위해서는 그룹을 지정해야 합니다. 그런데 아무런 장치가 없으면 그룹이라는게 생기지 않습니다. 다음과 같은 소스를 만들어 web.xml에 추가합니다.
위의 경우는 무조건 mygroup 라는 캐시 그룹만 생성합니다. 즉 모든 요청의 캐시는 위 그룹이 들어가죠.
web.xml 은 다음과 같이 변경합니다.
2. Cache 삭제 서비스 생성
다음과 같은 소스로 cache를 삭제하는 서블릿이나 action을 만듭니다.
정보를 갱신하여 cache를 다시 만들고 싶을때 위 소스가 실행되는 url 요청을 하면 됩니다.
내가 적용한 곳은 하루마다 배치 작업 후 갱신이 필요한 페이지라 배치 작업 후 위의 서비스 URL로 캐시를 날리고 다시 캐싱하기 위해 각 페이지 URL을 호출하는 배치 작업을 만들었습니다.
온라인으로 캐시를 갱신하기 위해서는 하나하나 캐시 갱신을 위한 판단을 할 필요가 있기에 캐시키를 생성하는 ICacheKeyProvider와 캐시 전략을 결정하는 EntryRefreshPolicy 인터페이스를 잘 살펴봐야 합니다.
기본에 충실하자
이 방법은 튜닝 후 맨 마지막에 하시기를 권합니다. 캐싱이 막강한 튜닝방법 중 하나이지만 마구 썼다가는 아키텍처가 무지 복잡해집니다(갱신 문제, 동기화 문제, 분산 캐싱...). 우선 각 기능을 충실하게 튜닝하고 난 후 캐싱이 효과적인 부분을 선택하여 쓰시기 바랍니다. 너무 캐싱에 의지하지 마세요~
WAS를 기동할 때 -javaagent 옵션을 주어야 합니다. Tomcat의 경우 기동하기 전 다음과 같이 하면 됩니다.
아래 set CATALINA_OPTS 부분은 한줄입니다.
prompt> cd C:\Tomcat\bin -> tomcat home의 bin 디렉토리로 이동
prompt> set CATALINA_OPTS=-javaagent:C:\Tools\jip-src-1.1.1\profile\profile.jar -Dprofile.properties=C:\Tools\jip-src-1.1.1\profile\webapp.profile.properties
prompt> catalina.bat run
...
기동하기전 프로파일할 대상을 필터링하려면 webapp.profile.properties 중 exclude 를 아래와 같은 예로 수정합니다. 아래는 org, net. com.sun. java. javax 로 시작하는 클래스는 프로파일을 하지 않겠다는 뜻입니다. 우리 관심 대상이 아닌 클래스는 프로파일에서 제외하는게 좋습니다.
...
exclude=org, net, com.sun, java, javax
...
프로파일 시작
webapp.profile.properties 설정은 WAS 기동시 프로파일이 자동으로 되지 않습니다. WAS 기동시 프로파일 정보는 필요없기 때문에 web app은 이런 설정이 좋습니다. WAS 기동이 끝나고 테스트할 기능을 한 두번 수행해보고 다음과 같이 프로파일 기록을 시작합니다.
prompt> cd C:\Tools\jip-src-1.1.1\client
prompt> start.bat localhost 15599
테스트 수행
테스트할 기능을 몇 번 수행합니다. 한번 수행하고 기록을 끝내는 것보다는 여러 번하고 기록하는 것이 분석하기 좋습니다.
프로파일 끝/기록
프로파일을 끝내야 프로파일 기록이 남습니다. C:\Tools\jip-src-1.1.1\client 디렉토리에서 다음과 같은 명령을 입력합니다.
prompt> finish.bat localhost 15599
그러면 tomcat을 실행했던 bin 디렉토리에 profile.xml 파일이 생길겁니다. C:\Tools\jip-src-1.1.1\client 디렉토리에서 다음과 같은 명령을 입력하여 분석결과를 봅니다.
prompt> jipViewer.bat C:\Tomcat\bin\profile.xml
분석
아래와 같은 화면이 나타날 겁니다. 시간이 많이 걸린 thread를 찾아 call tree를 따라가면 어떤 클래스의 어떤 메소드가 몇번 호출되었는지 얼마나 시간을 소요했는지 알 수 있습니다.
메소드 별로 호출회수나 소요시간을 정렬해서 볼 수 있습니다.
패키지 별로 소요시간을 얼마나 사용했는지 볼 수 있습니다.
Maven jetty 환경에서...
우리는 maven2에 jetty 환경에서 주로 개발을 합니다. maven의 jetty 플러그인으로 하려면 약간의 작업이 필요합니다.
우선 아래 첨부된 파일을 C:\Tools\jip-src-1.1.1\
src\com\mentorgen\tools\profile\instrument\clfilter 디렉토리에 넣고 ant로 컴파일합니다.
maven jetty:run 하기 전 -javaagent 옵션을 주기 위해 다음과 같은 환경변수를 잡습니다. 한줄입니다.
prompt> set MAVEN_OPTS=-javaagent:C:\Tools\jip-src-1.1.1\profile\profile.jar -Dprofile.properties=C:\Tools\jip-src-1.1.1\profile\webapp.profile.properties
Java 애플리케이션이 상태가 안좋거나 멈추었을때 JVM에서 무슨일이 벌어지고 있는지 정확히 찾는 방법으로 thread dump를 수행하면 아주 유용합니다. 특히 어떤 코드가 무한 루프 돌던가 어떤 코드블럭을 나오지 못할 경우 거의 바로 찾을 수 있습니다.
Thread dump가 무한루프나 코드블럭을 빠져나오지 못하는 곳을 바로 표시하거나 하는건 아니고 thread dump 남길 당시의 각 쓰레드의 stack trace를 보여주어 그 당시 수행하고 있는 java 메소드를 볼 수 있습니다. 문제를 풀 수 있는 좋은 출발점이 될 수 있습니다.
한 시점의 JVM 쓰레드의 각 stack 상태를 보는 것이기 때문에 문제가 발생한 시점에 약간의 간격을 두어 몇 번 남기고 비교하는게 좋은 방법입니다.
Thread dump 를 남기자
■ Windows
Windows에서 thread dump를 남기려면 command console 에서 java 애플리케이션을 실행해야 합니다. 쓰레드 덤프를 남기려는 시점에 Ctrl-Break 를 console에서 입력합니다.
■ Unix/Linux
간단히 thread dump를 남기고 싶은 JVM process에 SIGQUIT 시그널을 보냅니다.
prompt> kill -SIGQUIT process_id
또는
prompt> kill -3 process_id
* java 프로세스 아이디를 찾으려면 ps axf | grep java 하면 되겠습니다.
Thread dump를 보자
Thread dump는 그냥 text 형태의 매우 긴 로그입니다. 따라서 여러개의 thread dump를 그냥 날로 보려면 좀 피곤합니다. thread dump를 쉽게 분석할 수 있는 몇 가지 도구가 있겠지만 그 중 Samurai 이용해 보면 좋습니다. (다른 건 써 본적이 없어서...)
threaddump.jsp
