Translate

[JEUS][버그] UserAccessFormatter.java 에서 Lock 이 걸린경우

날짜:



환경 및 구성
OS: Redhat Enterprise
WEB: WebtoB 4.1 SP 7 Fix #1
WAS: JEUS 6.0 (Fix#8) - 6.0.0.8-b288
DBMS: Oracle
Application: JAVA(Spring+iBatis etc)




증상
WAS의 응답이 점점 느려지다가 현재는 대부분의 요청을 처리할 수 없게 됨.
(페이지가 뜨지 않음)







증상확인

1. 시스템 리소스 확인 (CPU, Memory, I/O)


[was:WAS1:/proc/4473] sar 1 100
Linux 2.6.18-371.9.1.el5 (WAS1) 2015 01 05

  CPU     %user     %nice   %system   %iowait    %steal     %idle
  all      7.46      0.00      2.49      0.00      0.00     90.05
 all      7.00      0.00      2.50      0.00      0.00     90.50
  all      5.00      0.00      2.50      0.00      0.00     92.50
 all     19.90      0.00      3.48      0.00      0.00     76.62
  all      3.50      0.00      1.50      0.50      0.00     94.50
 all     17.91      0.00      3.98      0.00      0.00     78.11
  all      7.50      0.00      4.50      0.00      0.00     88.00
 all      5.47      0.00      1.99      0.00      0.00     92.54
  all      5.56      0.00      1.01      0.00      0.00     93.43
 all      8.96      0.00      2.49      0.00      0.00     88.56

 [was:WAS1:/proc/4473]
[was:WAS1:/proc/4473]
[was:WAS1:/proc/4473] vmstat 1 100
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 400792  38380  48812 1092324    0    0   233   107    1    2  7  2 91  0  0
 3  0 400792  38388  48828 1092272    0    0     0    36 2280 5615  6  2 93  0  0
 1  0 400792  38388  48836 1092264    0    0     0   892 2736 5943  9  3 87  0  0
 2  0 400792  38256  48836 1092364    0    0     0    16 2588 6655  9  4 88  0  0
 0  0 400792  38132  48844 1092356    0    0     0    36 2150 5528  9  4 87  0  0
 0  0 400792  38008  48844 1092432    0    0     0     0 2362 5862  8  2 90  0  0
 4  0 400792  38008  48860 1092564    0    0     0    24 2314 5621  8  2 91  0  0
 0  0 400792  37884  48868 1092580    0    0     0   372 2218 5256 10  3 88  0  0
 0  0 400792  37760  48876 1092720    0    0     0    52 2451 5485  9  1 89  0  0
 0  0 400792  37644  48884 1092808    0    0     0    20 2653 6248 14  4 82  0  0
 4  0 400792  37644  48884 1092808    0    0     0     0 2223 5717  5  2 93  0  0
 0  0 400792  37644  48884 1092936    0    0     0     0 2842 5894 12  3 85  0  0
 0  0 400792  37520  48892 1092928    0    0     0   520 2571 5719  7  3 91  0  0
 5  0 400792  37388  48908 1093092    0    0     0   120 3174 6210 15  5 80  0  0
 3  0 400792  37388  48956 1093192    0    0     0   112 3969 7281 21  8 71  0  0
 0  0 400792  37388  48964 1093292    0    0     0    36 3044 5766 18  2 80  0  0
 0  0 400792  37388  48964 1093292    0    0     0     0 2503 6158  9  4 88  0  0
 3  0 400792  37496  48972 1093484    0    0     0   548 3908 6011 25  4 72  0  0
 0  0 400792  37744  48988 1093468    0    0     0   112 1642 4813  4  1 95  0  0
 1  0 400792  37744  48996 1093548    0    0     0    20 1908 5366  8  4 88  0  0
 3  0 400792  37620  48996 1093548    0    0     0     0 1733 4794  6  1 94  0  0
 3  0 400792  37512  49004 1093628    0    0     0    92 2866 5876 15  5 81  0  0

 [was:WAS1:/proc/4473]






2. Thread Dump 생성 및 확인
    - 'kill -3 pid' 명령어가 권한문제로 수행되지 않아서 'jstack pid' 방법으로 덤프를 생성

WAS1_ThreadDump_20150105.log (덤프파일 다운로드)
(위험하다고 판단되는 정보를 제거를 했으나 분석하는데에는 문제 없음)

덤프 생성시간
      01) 15:40:44
      02) 15:40:47
      03) 15:40:50
      04) 15:40:54
      05) 15:40:57
      06) 15:41:00
      07) 15:41:03
      08) 15:41:06
      09) 15:41:09
      10) 15:41:11



"webtob2_WAS1-hth2(???.???.???.???:19902)-w10 [WAS1-99]" prio=10 tid=0x0000000058db7000 nid=0x11f6 waiting for monitor entry [0x00002ad90430b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at jeus.util.logging.UserAccessFormatter.format(UserAccessFormatter.java:544)
- waiting to lock <0x00000000c00bae08> (a jeus.util.logging.UserAccessFormatter)
at jeus.util.logging.StreamHandler.writeRecord(StreamHandler.java:150)
at jeus.util.logging.StreamHandler.publish(StreamHandler.java:144)
at java.util.logging.Logger.log(Logger.java:478)
at jeus.util.logging.AccessLogger.log(AccessLogger.java:34)
at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:367)

 "webtob2_WAS1-hth2(???.???.???.???:19902)-w09 [WAS1-98]" prio=10 tid=0x0000000059532800 nid=0x11f5 waiting for monitor entry [0x00002ad90420a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at jeus.util.logging.UserAccessFormatter.format(UserAccessFormatter.java:544)
- waiting to lock <0x00000000c00bae08> (a jeus.util.logging.UserAccessFormatter)
at jeus.util.logging.StreamHandler.writeRecord(StreamHandler.java:150)
at jeus.util.logging.StreamHandler.publish(StreamHandler.java:144)
at java.util.logging.Logger.log(Logger.java:478)
at jeus.util.logging.AccessLogger.log(AccessLogger.java:34)
at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:367)

 "webtob2_WAS1-hth2(???.???.???.???:19902)-w08 [WAS1-97]" prio=10 tid=0x0000000059530800 nid=0x11f4 waiting for monitor entry [0x00002ad904109000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at jeus.util.logging.UserAccessFormatter.format(UserAccessFormatter.java:544)
- waiting to lock <0x00000000c00bae08> (a jeus.util.logging.UserAccessFormatter)
at jeus.util.logging.StreamHandler.writeRecord(StreamHandler.java:150)
at jeus.util.logging.StreamHandler.publish(StreamHandler.java:144)
at java.util.logging.Logger.log(Logger.java:478)
at jeus.util.logging.AccessLogger.log(AccessLogger.java:34)
at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:367)

 "webtob2_WAS1-hth2(???.???.???.???:19902)-w07 [WAS1-96]" prio=10 tid=0x00000000591ea000 nid=0x11f3 runnable [0x00002ad904008000]
   java.lang.Thread.State: RUNNABLE
at java.net.Inet4AddressImpl.getHostByAddr(Native Method)
at java.net.InetAddress$1.getHostByAddr(InetAddress.java:853)
at java.net.InetAddress.getHostFromNameService(InetAddress.java:533)
at java.net.InetAddress.getHostName(InetAddress.java:476)
at java.net.InetAddress.getHostName(InetAddress.java:448)
at jeus.servlet.engine.HttpServletRequestImpl.getRemoteHost(HttpServletRequestImpl.java:916)
at jeus.util.logging.UserAccessFormatter.format(UserAccessFormatter.java:586)
- locked <0x00000000c00bae08> (a jeus.util.logging.UserAccessFormatter)
at jeus.util.logging.StreamHandler.writeRecord(StreamHandler.java:150)
at jeus.util.logging.StreamHandler.publish(StreamHandler.java:144)
at java.util.logging.Logger.log(Logger.java:478)
at jeus.util.logging.AccessLogger.log(AccessLogger.java:34)
at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:367)

 "webtob2_WAS1-hth2(???.???.???.???:19902)-w06 [WAS1-95]" prio=10 tid=0x0000000058502000 nid=0x11f2 waiting for monitor entry [0x00002ad903f07000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at jeus.util.logging.UserAccessFormatter.format(UserAccessFormatter.java:544)
- waiting to lock <0x00000000c00bae08> (a jeus.util.logging.UserAccessFormatter)
at jeus.util.logging.StreamHandler.writeRecord(StreamHandler.java:150)
at jeus.util.logging.StreamHandler.publish(StreamHandler.java:144)
at java.util.logging.Logger.log(Logger.java:478)
at jeus.util.logging.AccessLogger.log(AccessLogger.java:34)
at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:367)






3. 시스템계정 환경설정 및 해당 컨테이너 정보 확인


[was:WAS1:/home/was] ulinmimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 46648
max locked memory       (kbytes, -l) 32
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 46648
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited
[was:WAS1:/home/was] 
[was:WAS1:/proc/4473/fd] ls -l | wc -l

413











증상분석

1. 시스템리소스
    - 별다른 문제가 보이지 않는다.


2. ThreadDump
    1) 대부분의 Thread 에서 AccessLog 클래스의 Lock 때문에 BLOCKED 상태가 되었다.
    2) LOCK 을 걸고 수행하는 Thread 는 JEUS 에서 Log를 수행중 getHostName 메소드를 수행을 했다.
    3) 덤프 파일의 15:40:57, 15:41:00 시간의 덤프 두개를 확인해보면 동일한 Thread(tid=0x0000000057f9d800) 에서 Reverse DNS query 수행중인 것을 확인 할 수 있다.(우연히 동일한 Thread 에 DNS 질의를 했다면 그나마 다행이겠지만 DNS의 응답이 늦어 처리가 되지 않은 상황이라면 직접적인 위험요소가 된다.)


3. Openfiles 설정 및 컨테이너의 파일 열려진 개수
    1) 쉘 및 프로세스당 open 가능한 file 개수가 1024 로 낮게 잡혀있다.
    2) JEUS 컨테이너가 열고 있는 파일 개수는 413개 정도로 보여진다.
      (413개의 수치는 WAS에서 사용하는 Lib jar파일, Log파일, Socket파일(Request) 등등이 포함된 수치다.)
    - ulimit 의 openfiles 설정이 1024 라는 수치로 낮게 잡혀있지만 현재 발생한 증상에 직접적인 관계는 없어 보인다.










원인

1. AccessLog 설정부분

  1) AccessLog 를 남기는 여부!?
    - 보통 AccessLog 는 웹서버(apache, webtob) 쪽에만 설정을 하는게 일반적인데 JEUS 에 AccessLog 가 남기게 설정이 되어있다.

  2) format의 잘못된 설정
    - JEUS 설정을 확인해보니 AccessLog 의 format 이 다음과 같이 설정되어 있었다.
        [%{yyyy.MM.dd HH:mm:ss}t] %a “%m %U%q” %u %h %s %S %b %D

    - %h 라는 설정은 Remote host name 을 저장하는 옵션인데 Reverse DNS query 가 필요한 부분이다.
      모든 Request 에 대해서 DNS에 조회를 해야 하며 DNS조회 하는 시점에서는 나머지 Thread 가 BLOCKED 되어버려 퍼포먼스에 문제가 발생을 하게된다.


2. JEUS 의 로직문제

  1) JEUS 버그이슈!?
    - AccessLog 의 %h 옵션이 무슨 문제가 있겠는가?? 쓰라고 만들어 놓은 옵션인데..
      원인을 찾다가 답답한 나머지 JEUS의 코어 파일인 jeus.jar 파일을 디컴파일하여 분석했다.
      UserAccessFormatter Class의 format Method 를 확인해보니 Method 에 static 키워드가 걸려있었다.
      그러니 모든 Thread 에서 Lock 이 걸리는게 당연한 문제..
      해당 Method 에서 static 이 사용된 이유는 로그파일에 기록을 하는 로직이 들어있어서 사용을 한 듯 하지만 DNS질의가 필요하다면 해당 부분은 static 밖으로 빼야 하는게 맞다.
      만일 DNS설정이 잘못되어 있거나 응답이 10초가 걸려버리면 바로 WAS hang 문제가 발생이 될 수 있는 상황..;;




* JEUS_6_Web_Container.pdf
   다운로드 (링크1, 링크2)





조치방법

1. AccessLog 설정

  1) AccessLog 를 웹서버(apache, webtob)쪽에만 설정을 하고 JEUS는 설정을 삭제한다.

  2) format 옵션에서 %h 옵션을 제거한다.


2. JEUS 의 핫픽스 및 버그이슈 확인

  - 위의 상황이라면 분명 제우스의 버그라고 봐도 될 듯 하다.
    아마 핫픽스나 버그이슈가 있어서 버전을 올리던지 하는 이슈가 있지 않을까 싶다.







조치 후

중간중간 페이지가 안뜨거나 하는 부분이 확실히 개선이 되었다.
아마 WAS 서버에 설정된 DNS서버의 응답이 최근에 느려져서 최근에 이런 증상이 발생하지 않았나 싶다.



이후 상황

JEUS 컨테이너 소프트웨어를 제작한 TmaxSoft 측에서 자사의 버그를 인정했으며, 추후 해당 이슈에 대한 퍼포먼스 이슈를 수정한 패치를 진행했었다.



댓글

댓글 쓰기