[CPU 과점유] AIX 편

 

본 포스팅은 SunOS, Solaris 서버의 CPU 과점유 현상 발생 시 대처 방안을 가이드합니다.

---

성능을 측정하는데는 여러가지 요소가 있습니다.

그중 중요한 CPU는 WEB/WAS 뿐만아니라 H/W, Network등의 병목을 유발하는 주요 성능 포인트 입니다.

그럼 CPU 성능 이슈가 발생했을 때 어떻게 처리해야 할 지 OS별로 알아보도록 하겠습니다.

 

AIX 편입니다.

다양한 방법을 통해 CPU 사용률을 확인할 수 있으나, ps 명령어를 통해 확인하는 방법을 가이드 하도록 하겠습니다.

 

1. ps

thread 별 CPU 사용률을 확인합니다.

ex) ps -mp process_pid -o THREAD

[nrson@ibmtest:/home/nrson]$ ps -mp 6070442 -o THREAD
    USER      PID     PPID       TID S  CP PRI SC    WCHAN        F     TT BND COMMAND
   nrson  6070442 15667394         - A   1  60 91        *   202001  pts/8   - /usr/java6_64//bin/java -Dserver1 -Xmx1024m -XX:MaxPermSize=128m -Xbootclasspath/p:/h
       -        -        -   1241191 S   0  62  1 f100010032740e78   400400      -   - -
       -        -        -   1581225 S   0  82  1 f100070f10018240  8410400      -   - -
       -        -        -   1638607 S   0  82  1 f100070f10019040  8410400      -   - -
       -        -        -   2003021 S   0  82  1 f100070f1001e940  8410400      -   - -
       -        -        -   2338981 S   0  62  1 f10001001017df98   410400      -   - -
       -        -        -   2363465 S   0  82  1 f100070f10024140  8410400      -   - -
       -        -        -   2392109 S   0  82  1 f100070f10024840  8410400      -   - -
       -        -        -   2416839 S   0  68  1 f100070f10024e40  8410410      -   - -
       -        -        -   2588831 S   0  82  1 f100070f10027840  8410400      -   - -
       -        -        -   3014821 S   0  60  1 f100070f1002e040  8410400      -   - -
       -        -        -  17039501 S   0  82  1 f100070f10104040  8410400      -   - -
...

...
[nrson@ibmtest:/home/nrson]$

상단의 결과는 JEUS7 MS PID를 확인한 결과 입니다.

while.jsp를 실행한 이후의 결과입니다.

[nrson@ibmtest:/home/nrson]$ ps -mp 6070442 -o THREAD
    USER      PID     PPID       TID S  CP PRI SC    WCHAN        F     TT BND COMMAND
   nrson  6070442 15667394         - A 120  60 91        *   202001  pts/8   - /usr/java6_64//bin/java -Dserver1 -Xmx1024m -XX:MaxPermSize=128m -Xbootclasspath/p:/h
       -        -        -   1241191 S   0  62  1 f100010032740e78   400400      -   - -
       -        -        -   1581225 S   0  82  1 f100070f10018240  8410400      -   - -
       -        -        -   1638607 S   0  82  1 f100070f10019040  8410400      -   - -
       -        -        -   2003021 Z   0  82  1        -   c00001      -   - -
       -        -        -   2338981 S   0  62  1 f10001001017df98   410400      -   - -
       -        -        -   2363465 S   0  82  1 f100070f10024140  8410400      -   - -
       -        -        -   2392109 S   0  82  1 f100070f10024840  8410400      -   - -
       -        -        -   2416839 S   0  68  1 f100070f10024e40  8410410      -   - -
       -        -        -   2588831 S   0  82  1 f100070f10027840  8410400      -   - -
       -        -        -   3014821 S   0  60  1 f100070f1002e040  8410400      -   - -
       -        -        -   3084463 S   0  82  1 f100010032c8e978   400400      -   - -
       -        -        -   3285055 S   0  82  1 f100070f10032240  8410400      -   - -
       -        -        -   3522583 S   0  82  1 f100070f10035c40  8410400      -   - -
       -        -        -   3793031 S   0  60  1 f100070f10039e40  8410400      -   - -
       -        -        -   3989533 S   0  82  1 f100070f1003ce40  8410400      -   - -
       -        -        -   4186305 S   0  82  1 f100070f1003fe40  8410400      -   - -
       -        -        -   4345943 S   0  62  1 f100010032740d78   400400      -   - -
       -        -        -   4456507 S   0  82  1 f100070f10044040  8410400      -   - -
       -        -        -   4464817 Z   0  82  1        -   c00001      -   - -
       -        -        -   4497577 S   0  82  1 f100070f10044a40  8410400      -   - -
       -        -        -   4792475 S   0  82  1 f100070f10049240  8410400      -   - -
       -        -        -   5255385 S   0  82  1 f100070f10050340  8410400      -   - -
       -        -        -   5521441 S   0  82  1 f10001005f69d530   410400      -   - -
       -        -        -   5824551 S   0  82  1 f100070f10058e40  8410400      -   - -
       -        -        -   5853221 S   0  82  1 f100070f10059540  8410400      -   - -
       -        -        -   6095079 S   0  82  1 f100070f1005d040  8410400      -   - -
       -        -        -   6250723 S   0  82  1 f100070f1005f640  8410400      -   - -
       -        -        -   6725659 S   0  82  1 f100070f10066a40  8410400      -   - -
       -        -        -   6897835 S   0  82  1 f100070f10069440  8410400      -   - -
       -        -        -   7016575 S   0  60  1 f10001002d598798   410400      -   - -
       -        -        -   7114881 S   0  82  1 f100070f1006c940  8410400      -   - -
       -        -        -   7143549 S   0  82  1 f100070f1006d040  8410400      -   - -
       -        -        -   7499913 S   0  82  1 f100070f10072740  8410400      -   - -
       -        -        -   7905475 S   0  82  1 f100070f10078a40  8410400      -   - -
       -        -        -   8401127 S   0  82  1 f100070f10080340  8410400      -   - -
       -        -        -   8786095 S   0  82  1 f100070f10086140  8410400      -   - -
       -        -        -   8798301 S   0  82  1 f100070f10086440  8410400      -   - -
       -        -        -   8868007 R 120 162  0        -   400000      -   - -
...

...
[nrson@ibmtest:/home/nrson]$

CP가 급격하게 증가한 Thread가 보입니다. TID인 8868007을 기억하고 Thread Dump를 생성합니다.

 

2. Thread Dump 생성

먼저 Sun HotSpot 계열 Thread Dump에 대해 간단히 살펴 보고 넘어가도록 하겠습니다.

Thread Dump 생성

- Java process에 signal을 전달하여 생성합니다. (SIGQUIT)
- Java process를 만든 벤더들이 내부적으로 SIGQUIT에 대한 signal을 catch하여 그 시점의 stack trace를 출력하는 것입니다.
- Unix 계열 (Sun, HP-UX, AIX, Linux 등)
# kill -3 [프로세스 ID]

 

생성 위치

- IBM 계열의 경우 Thread dump 생성을 수행하기 위해 kill 명령을 수행하면 STDOUT으로 출력되지 않고 javacore라는 파일을 생성시켜 출력하게 됩니다. 해당 파일에 대한 위치는 “IBM_JAVACOREDIR” 이라는 환경변수 설정을 통해 디렉토리를 지정할 수 있습니다. 해당 환경변수를 설정하지 않았을 경우 javacore 파일이 생성되는 위치를 확인하기 위해서는 다음과 같은 명령을 통해 알 수 있습니다.

​[ibmtest:nrson:/home/nrson] java -Xdump:java:defaults

Default -Xdump:java settings:

  events=gpf+user
  filter=
  file=/home/nrson/javacore.%Y%m%d.%H%M%S.%pid.%seq.txt
  range=1..0
  priority=400
  request=exclusive+preempt
  opts=

​IBM JVM에서는 dump agent를 통해 각종 dump 파일(system dump, heap dump, snap trace, java 등)들을 생성하기 위한 설정을 제어할 수 있습니다.

 

# 참조 Thread 상태 정보

Sun 계열의 경우 Thread dump 수행 시점의 간단한 Thread들의 정보와 Stack trace 정도만 제공해 주시만, IBM의 Thread dump는 수행 지점의 JVM 프로세스에 대한 매우 상세한 정보를 제공합니다.

[생성 위치]
- 우선순위 1. IBM_JAVACOREDIR 환경 변수 설정 디렉토리
- 우선순위 2. JVM 프로세스의 현재 Working directory
- 우선순위 3. TMPDIR 환경 변수가 설정된 디렉토리
- 우선순위 4. /tmp 디렉토리
[파일 포멧]
- 파일명 “javacore.%Y%m%d.%H%M%S.%pid.txt”
[IBM JVM subcomponent structure]
- CI(Core Interface) : User, 외부 프로그램, 환경에 관련된 인터페이스를 담당합니다.
- XM(Execution Management) : 다중 수행 엔진(Multiple execution engine)의 관리와  프로세스 control 기능을 제공합니다.
- DG(Diagnostics) : 각종 진단 기능과 서비스 디버그 기능 그리고 도구들을 제공합니다.
- XE(Execution Engine) : Byte code를 수행하기 위한 다양한 방법을 제공합니다.
- CL(Class Loader) : Java class들의 위한 모든 지원 기능들을 제공합니다.
- DC(Data Conversion) : 다양한 format들간의 data 변경 기능들을 제공합니다.
- LK(Lock) : Locking과 Synchronization 서비스 기능들을 제공합니다.
- ST(Storage) : Storage 서비스(메모리) 부분에 대한 기능들을 제공합니다.
- HPI(Hardware Platform Interface) : Low-level facility와 다양한 platform에 대한 서비스에 대한 기능들을 제공합니다.

 

3. Thread Dump 분석

Thread Dump를 편집기로 오픈 한 후 pstack으로 확인한 thread# 85를 HEX로 변환한 결과 값과 nid값을 매칭되는 값을 찾습니다.

[nrson@ibmtest:/home/nrson]$ ps -ef | grep java | grep server1
   nrson  6070442 15667394 120 15:11:06  pts/8  9:47 /usr/java6_64//bin/java -Dserver1 -Xmx1024m -XX:MaxPermSize=128m -Xbootclasspath/p:/home/nrson/jeus7/lib/system/extension.jar -classpath /home/nrson/jeus7/lib/system/bootstrap.jar -Djava.security.policy=/home/nrson/jeus7/domains/jeus_domain/config/security/policy -Djava.util.logging.manager=jeus.util.logging.JeusLogManager -Djava.library.path=/home/nrson/jeus7/lib/system -Djava.endorsed.dirs=/home/nrson/jeus7/lib/endorsed -Djava.util.logging.config.file=/home/nrson/jeus7/bin/logging.properties -Djeus.dispatcher.blocking=true -Djeus.home=/home/nrson/jeus7 -Djava.util.logging.manager=jeus.util.logging.JeusLogManager -Djava.net.preferIPv4Stack=true -Djava.util.prefs.PreferencesFactory=java.util.prefs.FileSystemPreferencesFactory -Djeus.properties.replicate=jeus,sun.rmi,java.util,java.net -Djeus.tool.webadmin.locale.language=ko -Djeus.jvm.version=old -Djeus.domain.name=jeus_domain -Djava.naming.factory.initial=jeus.jndi.JNSContextFactory -Djava.naming.factory.url.pkgs=jeus.jndi.jns.url -Djeus.server.protectmode=false jeus.server.ServerBootstrapper -domain jeus_domain -server server1 -u administrator
[nrson@ibmtest:/home/nrson]$ kill -3 6070442
[nrson@ibmtest:/home/nrson]$ ls -alrt
total 840
drwxr-xr-x   46 bin      bin            4096 May 18 16:03 ..
-rw-rw-r--    1 nrson    ia             2045 May 18 16:10 .profile76216155
-rw-rw-r--    1 nrson    ia             2370 May 22 14:24 .profile1112481941
-rw-rw-r--    1 nrson    ia             2767 May 22 14:35 .profile813678693
-rw-r--r--    1 nrson    ia             3163 May 22 14:35 .profile
drwxr-xr-x   14 nrson    ia             4096 May 22 14:35 jeus7
-rwxrwxrwx    1 nrson    ia             1978 May 22 14:35 .com.zerog.registry.xml
drwxr-xr-x    2 nrson    ia              256 May 22 15:09 .jeusadmin
drwxr-xr-x    3 nrson    ia              256 May 22 15:11 application
-rw-------    1 nrson    ia               59 May 22 15:12 .vi_history
-rw-r--r--    1 nrson    ia           384378 May 22 15:27 javacore.20170522.152751.6070442.0001.txt
drwxr-xr-x    5 nrson    ia             4096 May 22 15:27 .
-rw-------    1 nrson    ia             1602 May 22 15:27 .sh_history
[nrson@ibmtest:/home/nrson]$ vi javacore.20170522.152751.6070442.0001.txt

NULL           ------------------------------------------------------------------------
0SECTION       TITLE subcomponent dump routine
NULL           ===============================
1TISIGINFO     Dump Event "user" (00004000) received
1TIDATETIME    Date:                 2017/05/22 at 15:27:51
1TIFILENAME    Javacore filename:    /home/nrson/javacore.20170522.152751.6070442.0001.txt
1TIREQFLAGS    Request Flags: 0x81 (exclusive+preempt)
1TIPREPSTATE   Prep State: 0x104 (exclusive_vm_access+)
NULL           ------------------------------------------------------------------------
0SECTION       GPINFO subcomponent dump routine
NULL           ================================
2XHOSLEVEL     OS Level         : AIX 5.3
2XHCPUS        Processors -
3XHCPUARCH       Architecture   : ppc64
3XHNUMCPUS       How Many       : 4
3XHNUMASUP       NUMA is either not supported or has been disabled by user
NULL
1XHERROR2      Register dump section only produced for SIGSEGV, SIGILL or SIGFPE.
NULL
NULL           ------------------------------------------------------------------------
0SECTION       ENVINFO subcomponent dump routine
NULL           =================================
1CIJAVAVERSION JRE 1.6.0 AIX ppc64-64 build jvmap6460sr15-20131231_180656 (pap6460sr15fp1-20140110_01(SR15 FP1))
1CIVMVERSION   VM build 20131231_180656
1CIJITVERSION  r9_20130920_46510ifx3
1CIGCVERSION   GC - GA24_Java6_SR15_20131231_1152_B180656
1CIJITMODES    JIT enabled, AOT enabled, FSD disabled, HCR disabled
1CIRUNNINGAS   Running as a standalone JVM

...

...

...

위와 같은 형태의 Thread Dump가 생성된 것을 확인할 수 있습니다.

 

자 그럼 앞서 PS 명령어로 확인한 tid를 16진수로 변환하여 확인해 보도록 하겠습니다.

8868007을 16진수로 변환하면 0x8750A7이며 이를 찾아 보니 아래와 같이 while.jsp를 수행중임을 알수 있습니다.

----

3XMTHREADINFO      "http1-1" J9VMThread:0x0000000114600600, j9thread_t:0x00000001145EB8F0, java/lang/Thread:0x0700000002B8BA60, state:CW, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x52, isDaemon:true)
3XMTHREADINFO1            (native thread ID:0x8750A7, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at jeus_jspwork/_700_while_5fjsp._jspService(_700_while_5fjsp.java from InMemoryJavaFile:68(Compiled Code))
4XESTACKTRACE                at org/apache/jasper/runtime/HttpJspBase.service(HttpJspBase.java:70)
4XESTACKTRACE                at javax/servlet/http/HttpServlet.service(HttpServlet.java:847)
4XESTACKTRACE                at jeus/servlet/jsp/JspServletWrapper.executeServlet(JspServletWrapper.java:66)
4XESTACKTRACE                at jeus/servlet/servlets/JspServlet.executeServlet(JspServlet.java:134)
4XESTACKTRACE                at jeus/servlet/servlets/JspServlet.execute(JspServlet.java:74)
4XESTACKTRACE                at jeus/servlet/engine/RequestProcessor.run(RequestProcessor.java:211)
4XESTACKTRACE                at jeus/util/ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:1211(Compiled Code))
4XESTACKTRACE                at jeus/util/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:1261(Compiled Code))
4XESTACKTRACE                at jeus/servlet/engine/WebThreadPoolExecutor$WebRequestWorker.run(WebThreadPoolExecutor.java:340)
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:761)

이후 분석 과정은 타 OS와 동일합니다.

 

4. 조치

WAS 엔지니어의 입장에서는 JSP 파일(상단의 Stack 정보를 통해 Compiled 된 jsp 파일을 찾을수 있음 - sleep.jsp)과 Compile java source를 전달하면 완료되지만, 직접 분석을 진행해 보도록 하겠습니다.

JSP 파일과 JAVA 파일을 열어보면 다음과 같습니다.

[sleep.jsp]

<%@ page contentType="text/html; charset=euc-kr" %>
<%
        int i=0;
        int sum=0;
        while (i<=0) {
                        sum=sum+i;
                        i=i++;
        }
%>

이거만 봐도... 문제가 있죠?? while문이 무한루프가 돌게 작성이 되어 있네요..

다만 단순한 소스가 아니고 Thread Dump 스택의 경우 아래와 같이 Compiled java source 기준으로 line(68)이 표시 되기 때문에 실제로는 java Source를 확인해야 합니다.

&quot;http1-13 [server1-487]&quot; daemon prio=10 tid=0x00007fb42400d000 nid=0x1e4f runnable [0x00007fb4687bc000]
   java.lang.Thread.State: RUNNABLE
        at jeus_jspwork._700_sleep_5fjsp._jspService(_700_sleep_5fjsp.java:68)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
        at jeus.servlet.jsp.JspServletWrapper.executeServlet(JspServletWrapper.java:66)
        at jeus.servlet.engine.ServletWrapper.execute(ServletWrapper.java:149)
        at jeus.servlet.jsp.JspServletWrapper.execute(JspServletWrapper.java:40)
        at jeus.servlet.engine.RequestProcessor.run(RequestProcessor.java:211)
        at jeus.util.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:1211)
        at jeus.util.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:1261)
        at jeus.servlet.engine.WebThreadPoolExecutor$WebRequestWorker.run(WebThreadPoolExecutor.java:340)
        at java.lang.Thread.run(Thread.java:722)

 

[_700_sleep_5fjsp.java] 

     51     try {
     52       response.setContentType("text/html; charset=euc-kr");
     53       pageContext = _jspxFactory.getPageContext(this, request, response,
     54                         null, true, 8192, true);
     55       _jspx_page_context = pageContext;
     56       application = pageContext.getServletContext();
     57       config = pageContext.getServletConfig();
     58       session = pageContext.getSession();
     59       out = pageContext.getOut();
     60       _jspx_out = out;
     61
     62       out.write('\n');
     63
     64         int i=0;
     65         int sum=0;
     66         while (i<=0) {
     67                         sum=sum+i;
     68                         i=i++;
     69         }
     70
     71       out.write('\n');
     72     } catch (java.lang.Throwable t) {
     73       if (!(t instanceof javax.servlet.jsp.SkipPageException)){
     74         out = _jspx_out;
     75         if (out != null && out.getBufferSize() != 0)
     76           try {
     77             if (response.isCommitted()) {
     78               out.flush();
     79             } else {
     80               out.clearBuffer();
     81             }
     82           } catch (java.io.IOException e) {}
     83         if (_jspx_page_context != null) _jspx_page_context.handlePageException(t);
     84         else throw new ServletException(t);
     85       }
     86     } finally {
     87       _jspxFactory.releasePageContext(_jspx_page_context);
     88     }
     89   }

68 라인에 가봤더니 동일한 위치에서 걸려 있네요.. 해당 부분의 수정이 필요하다는 것을 판단하고 개발자에게 전달하면 1Cycle 완료!

감사합니다.

# 댓글과 추천은 글쓴이에게 힘이됩니다.!