2011년 2월 14일 월요일

All threads (200) are currently busy, waiting. Increase maxThreads (200) or check the servlet status

2011. 2. 13 오후 9:26:36 org.apache.tomcat.util.threads.ThreadPool logFull
심각: All threads (200) are currently busy, waiting. Increase maxThreads (200) or check the servlet status

tomcat에서 이런 메세지를 종종 볼 수 있다.

다른건 필요없고 해당 원인이 발생되는 이유는
톰켓 내부에서 사용되는 쓰레드가 특정 코드에서 lock 걸리고
그 lock가 maxThreads(default:200)을 넘어버리면서 나는 현상이다.

그런데 이 문제를 해결하기 위해서 단순하게 maxThreads 값을 늘려버리는데,
이것은 근본적인 문제를 무시하고 단순히 2시간 뒤면 뻗을 서버가 3시간으로 연장하는
수준밖에 되지 않는다.

이런 문제점을 해결하기 위해서는 제니퍼(Jennifer) 같은 모니터링 서비스를 설치하는게 좋으나,
여건 상 불가능 한 경우가 많다.

* 하단에 다른 방법도 추가했습니다.- Probe를 이용 (2013-01-02)

하지만 방법이 없는 것은 아니다.

다행이도 대부분의 리눅스, 유닉스 시스템에서 java thread dump 기능을 제공한다.
이것을 모든 것을 파악하기는 힘들지만,
최소한 어디선가 발생하는지 원인을 파악할 수 있으니, 모름지기 큰 도움이 될것이며,
이것을 알아두면 더 좋은 스킬을 쌓을 수 있다.

구글창에 java thread dump 검색하면 수두룩하게 좋은 결과가 많으니,
공부하는 것도 좋다고 생각한다.

백마디 말보단 간단하게 예제소스를 적어주는 것이 도움이 되지 않겟는가?
환경 : SunOS + apache2 + tomcat5.5

# ps -ef grep java
root 1139 1 0 11월 27 ? 465:58 /usr/jdk/latest/bin/java -version:1.5+ -jar /usr/lib/patch/swupna.jar -wait
search 28634 1 0 11월 29 ? 670:24 /usr/jdk/j2sdk1.4.2_13/bin/java -Xmx256m -Xbootclasspath/a:/user/search/sf-1/wn
tomcat 26601 1 0 14:21:50 pts/8 9:33 /usr/java/bin/java -Djava.util.logging.config.file=/usr/local/tomcat/conf/loggi
root 8110 21046 0 15:58:16 pts/8 0:00 grep java

톰켓이라는 계정으로 실행된 프로세스가 확인된다. (요놈이 바로 톰켓 프로세스이다.)
계정명으로 확인이 안되면 뒤에 옵션면에 톰켓 폴더가 있는걸로 확인하면 된다.

빨간색을 표시되는것이 pid(프로세스아이디)이다.

해당 톰켓 프로세서 스레드덤프를 확인해보자.

# kill -3 26601
* 참고로 kill -3 명령어가 안 먹히는 경우에는 (보통 리눅스인)
# jstack 26601 을 활용하자.
이렇게 실행한 후에 tail 명령어로 catalina.out를 확인하자.

# cd $CATALINA_HOME
톰켓 홈 디렉토리로 이동
# cd logs
# tail -2000f catalina.out

...

확인하면 해당 OS벤더에 따른 java thread dump 내용을 확인할 수 있다.

본 인의 경우에는

"TP-Processor121" daemon prio=3 tid=0x005016f8 nid=0xca runnable [0xa90fe000..0xa90ff8f0]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.javaservice.lwst.SocketWrapper$InputStreamWrap.read(Unknown Source)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0xe48782f0> (a java.io.BufferedInputStream)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:681)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:626)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:974)
- locked <0xe4867208> (a sun.net.www.protocol.http.HttpURLConnection)
at org.apache.jsp.html.tsearch.XmlTrans_jsp.getHtmls(XmlTrans_jsp.java:32) at org.apache.jsp.html.tsearch.XmlTrans_jsp._jspService(XmlTrans_jsp.java:90)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:331)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:329)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:265)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Thread.java:595)

이런 내용이 존재하였는데

/html/tsearch/XmlTrans.jsp 소스 내부에서
BufferdInputStream 객체가 제대로 해제가 안되고
해당 메소드(getHtmls)의 파라메터도 제대로 넘어가지 않아서 해당 객체가 리퀘스트 자체가 lock가 걸려서 theard Poll 에서 full이 나는 경우였다.

다행히 관련 소스를 수정하니 더 이상 문제가 발생하지 않았다.

다들 java thread dump를 이용해서 관련 문제를 잘 해결하시길 바랍니다.


_________________________________________________________________________

더 좋은 방법이 있음!

Probe 라는 웹어플리케이션을 설치하면 됩니다.
일종의 모니터링 프로그램인데요. 제니퍼와 같은 상용에는 못 미치나
그럭저럭 사용할만 합니다.

단, tomcat에만 적용이 가능합니다.

https://code.google.com/p/psi-probe/downloads/detail?name=probe-2.3.3.zip

여기에서 최신 버전을 다운 받을 수 있습니다. (현재는 개발 중지 상태인 듯)

해당 War를 이용하여 설치하시고 톰켓 관리자 ($CATALINA_PATH/conf/tomcat-user.xml)
권한으로 로그인하면 사용이 가능합니다.

아래와 같은 화면을 통해서 GUI를 통해서 모니터링 및 각종 리소스 현황 등을 확인할 수 있습니다. Thread full과 관련해서는 Threads 라는 메뉴를 통해서 확인하시면 쓰레드가 지속적으로 lock 되는 부분을 확인 하는 것도 가능합니다.




Probe 좋네요 ㅇㅇ