빈번한 JSP 변경여부 체크에 의한 성능저하 - WAS Troubleshooting 사례(1)

빈번한 JSP 변경여부 체크에 의한 성능저하 - WAS Troubleshooting 사례(1)

OO기업의 OO시스템을 오픈하기 전에 성능테스트를 수행하는데 응답시간이 현저히 느려졌다.
해당 시스템은 4대의 Tomcat instance가 1개의 Storage를 Network Driver 연결로 쓰고 있으며 Oracle 11g를 DB로 사용하고 있었다.
오픈이 한 달 앞으로 다가온 상황에서 현재의 성능으로는 서비스를 개시할 수 없다.
과연 어떤 원인으로 응답속도가 현저히 저하되고 있는지 알아보도록 하자.

원인 파악을 위한 로그 분석 - Java 쓰레드 덤프

Java 쓰레드 덤프는 모든 JVM 관련 issue를 파악하기 위한 기본이 된다.
성능테스트를 위해 가상 부하를 점진적으로 높이는 시점부터 응답시간이 늘어나는 현상이 발생하니, 해당 시점부터 2~3초 간격으로 여러 차례 쓰레드 덤프를 확보해야 한다.

쓰레드 덤프를 확보하는 방법은 아래와 같이 2가지가 있다.

ps -ef | grep "keyword"

jps -v

위 방법으로 쓰레드 덤프를 확보하였더니 대부분의 쓰레드 스택이 다음과 같은 모양을 나타내고 있었다.

위 덤프를 자세히 보면 스택의 내용이 시스템의 비즈니스를 구현하는 클래스와 메소드가 아닌 Tomcat의 JSP Engine인 Jasper에 걸려있는 것을 알 수 있다. 즉, 대부분의 성능저하가 비즈니스 때문이 아닌 Tomcat의 내부 문제(?)에 의한 것이다. 물론 진짜 문제(Trouble)인지 아닌지는 좀 더 파악해 봐야 겠지만…

Tomcat JSP Engine(Jasper)의 소스 점검

Java 스택에 표시된 Jasper 부분의 병목을 파악하기 위해 Apache Site에서 소스코드를 다운로드 받아 분석해 보았다.

Tomcat은 오픈소스이기 때문에 아래 사이트에서 버전에 맞는 소스를 다운로드 받을 수 있다.

https://archive.apache.org/dist/tomcat/tomcat-6/

해당 시스템은 Tomcat 6.0.33 이므로 관련 소스를 받아 JspServletWrapper Class를 살펴 보면 다음과 같다.

위 소스를 보면 323 라인의 if 조건을 만족하면 324 라인의 synchronized 구문을 타기 때문에 부하가 많아지면 병목이 발생되고 응답시간이 느려질 수 밖에 없다.
쓰레드 덤프에 나타난 324 라인이 바로 이 부분에서 성능저하가 발생했음을 나타내고 있다.
이제 병목 지점을 찾아 냈으니 개선할 수 있는 방법을 찾아보자.

응답시간 저하 원인 - synchronized 구문

응답시간 저하의 원인이 synchronized 구문 때문이라는 것을 알았으니, 이제 이 부분을 회피할 수 있는 개선 방안을 찾으면 된다.
코드를 해석해 보면 options.getDevelopment()의 값이나 firstTime의 값이 TRUE이면 synchronized 구문을 타는 것을 알 수 있다.
그런데 synchronized 구문 안을 보면 firstTime을 false로 만들어버리므로 계속된(지속적인) 응답시간 저하가 firstTime 때문이라고는 볼 수 없다.
그러면 결론적으로 options.getDevelopment()의 값이 지속적으로 TRUE라는 의미가 되므로 이 값이 어떤 의미인지 파악하고 해당 값을 false로 만들 수만 있으면 지금 문제가 되는 성능저하를 개선할 수 있다.

Tomcat 옵션 설정에 따른 Compile 부하

이 options 객체를 추적해 보면 해당 객체가 Tomcat 기동 시에 web.xml 옵션을 저장하고 있는 객체이며 getDevelopment() 메소드는 development 항목값을 불러오는 것을 알 수 있다.

web.xml에 정의되어 있는 development 항목 설명을 살펴보자.

위 설명을 해석해 보면 다음과 같다.

Jasper가 개발모드로 사용되고 있는가? 만약 true 이라면, JSP의 변경여부를 체크하는 빈도수가 modificationTestInterval 옵션값에 의해 정의될 것이다. (기본값은 TRUE)

즉, developement 값이 TRUE이면 변경된 JSP의 Compile을 위해 변경여부를 주기적으로 체크하게 되는 것이다.
중요한 점은 developement 값을 지정하지 않으면 기본적으로 TRUE 값을 가지게 되는데, 본 시스템에서도 특별히 지정되지 않았으며 따라서 TRUE 값을 가지게 된 것이다.

이제 이러한 파악된 정보를 기반으로 소스코드를 다시 한 번 살펴보자.

결국 options.getDevelopment() 값이 항상 TRUE 이기 때문에 firstTime과 무관하게 항상 324 라인을 타게 되고 synchronized 구문 안에 있는 ctxt.compile()은 추정컨데, Context의 JSP 변경 여부를 체크하여 compile하는 역할인데 본 시스템에서는 1개 Storage를 Network Driver로 연결하여 4대 WAS가 사용하는 구조로 수 많은 JSP File의 변경 여부(last update time)를 체크하는데 다른 Site들보다 시간이 오래 걸리는 것이었다.

이로써 모든 원인이 파악이 되었으며, 개선 방안으로 web.xml에 아래와 같이 developement 값을 명시적으로 false로 표시해 주므로써 병목 부분을 해소할 수 있었으며 응답시간도 상당히 빨라져서 성능테스트를 무난히 성공할 수 있었다.

끗~