티스토리 뷰
본 포스팅은 SunOS, Solaris 서버의 CPU 과점유 현상 발생 시 대처 방안을 가이드합니다.
성능을 측정하는데는 여러가지 요소가 있습니다.
그중 중요한 CPU는 WEB/WAS 뿐만아니라 H/W, Network등의 병목을 유발하는 주요 성능 포인트 입니다.
그럼 CPU 성능 이슈가 발생했을 때 어떻게 처리해야 할 지 OS별로 알아보도록 하겠습니다
이번에는 SunOS 입니다.
SunOS의 경우 LINUX와 마찬가지로 top 명령어를 통해 확인이 가능하나, prstat을 통해 확인하는 방법을 가이드 하도록 하겠습니다.
1. prstat
모니터링할 PID를 확인합니다.
JEUS7 기준으로 다음과 같이 PID확인이 가능합니다.
[DAS]jeus_domain.adminServer>si
Information about Domain (jeus_domain)
================================================================================
+-------+---------+-----+-----+-----+------------+--------+-----------+--------+
| Server| Status | Node| PID | Clus| Latest | Need to| Listen | Running|
| | |Name | | ter |Start Time /|Restart | Ports |Engines |
| | | | | | Shutdown | | | |
| | | | | | Time | | | |
+-------+---------+-----+-----+-----+------------+--------+-----------+--------+
| adminS| RUNNING(| sunt| 9879| N/A | Thu May 18 | true | BASE-192.1| jms, |
|erver(*|00:14:16)|est | | |14:10:38 KST| |68.1.220:97|ejb, web|
|) | | | | |2017 | |36 | |
| | | | | | | | http-serve| |
| | | | | | | |r-192.168.1| |
| | | | | | | |.220:8808 | |
| | | | | | | | jms-intern| |
| | | | | | | |al-192.168.| |
| | | | | | | |1.220:9941 | |
+-------+---------+-----+-----+-----+------------+--------+-----------+--------+
|server1| RUNNING(| sunt|10148| N/A | Thu May 18 | false | BASE-192.1| jms, |
| |00:02:49)|est | | |14:21:56 KST| |68.1.220:99|ejb, web|
| | | | | |2017 | |36 | |
| | | | | | | | http-serve| |
| | | | | | | |r1-192.168.| |
| | | | | | | |1.220:8088 | |
| | | | | | | | jms-intern| |
| | | | | | | |al1-192.168| |
| | | | | | | |.1.220:9741| |
+-------+---------+-----+-----+-----+------------+--------+-----------+--------+
================================================================================
[DAS]jeus_domain.adminServer>
[nrson@suntest:/home/nrson]$ prstat
상대에서 확인한 pid를 활용하여 모니터링하기 위해 아래와 같이 입력합니다.
[nrson@suntest:/home/nrson]$ prstat -L -p 10148
자 그럼 LINUX편에서 다뤘던 것 처럼 무한루프를 돌려 강제로 CPU 점유를 늘려 보겠습니다.
[Call jsp]
http://nrson.tmax.co.kr:8088/while.jsp
[prstat 재확인]
[nrson@suntest:/home/nrson]$ prstat -L -p 10148
CPU 사용률 가장 높은 Thread가 고작 0.3%였던 해당 Process는 43%를 사용하는 Thread로 둔갑하였습니다.
2. pstack
10148: /usr/jdk1.7.0_10/bin/java -Dserver1 -Xmx1024m -XX:MaxPermSize=128m -se
----------------- lwp# 1 / thread# 1 --------------------
ff2c6a18 lwp_wait (2, ffbfe304)
ff2c2348 _thrp_join (2, 0, ffbfe3c8, 1, ffbfe304, ff2f3580) + 34
ff2c24b4 thr_join (2, 0, ffbfe3c8, ffbfe43c, 0, 0) + 10
ff3826f0 ContinueInNewThread0 (ff371498, 0, 80000, ffbfe43c, 10000, ff04a000) + 30
ff375aa4 ContinueInNewThread (feab7834, feab77a4, fe6c1608, ffbff858, 25c00, fffda128) + b0
ff382770 JVMInit (ffbfe5b0, ffbff858, 0, 6, 21368, 1) + 40
ff371488 JLI_Launch (11000, fffee3e8, fffeed70, 11c00, 0, fffee3f4) + 2d0
00010c08 main (10c8c, 0, 10c74, 10c74, 1b8, 0) + a4
00010734 _start (0, 0, 0, 0, 0, 0) + 108
...
...
...
----------------- lwp# 85 / thread# 85 --------------------
fbf1ced0 * *jeus_jspwork/_700_while_5fjsp._jspService(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V [compiled] +103 (line 110)
fbc06b84 * org/apache/jasper/runtime/HttpJspBase.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V+3 (line 140)
fbc06b84 * javax/servlet/http/HttpServlet.service(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+30 (line 1694)
fbc0771c * jeus/servlet/jsp/JspServletWrapper.executeServlet(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+131 (line 277)
fbc0771c * jeus/servlet/servlets/JspServlet.executeServlet(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+336 (line 221)
fbc06b84 * jeus/servlet/servlets/JspServlet.execute(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V+25 (line 144)
fbc0771c * jeus/servlet/engine/RequestProcessor.run()V+1099 (line 910)
fbc0771c * jeus/util/ThreadPoolExecutor$Worker.runTask(Ljava/lang/Runnable;)V+66 (line 2409)
fbc06b84 * jeus/util/ThreadPoolExecutor$Worker.run()V+76 (line 2501)
fbc06b84 * jeus/servlet/engine/WebThreadPoolExecutor$WebRequestWorker.run()V+1 (line 680)
fbc0771c * java/lang/Thread.run()V+11 (line 1443)
fbc0021c * StubRoutines (1)
fe5b031c __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (aaf7fde8, aaf7fd30, e, 5ecf000, f5ca0, b3824068) + 3a0
fea6eea0 __1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_pnGSymbol_6pnGThread__v_ (aaf7fde8, 5ecfa48, 5ecfa40, 2ee30, 2f040, ff565f7c) + 190
fe65fa30 __1cMthread_entry6FpnKJavaThread_pnGThread__v_ (6533c88, 127740, b3826478, 5ecfa44, ff171740, 127400) + 160
fee53818 __1cKJavaThreadRthread_main_inner6M_v_ (5ecf000, 5ecf640, 5ecf638, 5ecfa2c, aaf7fe78, 0) + 88
fe65b564 __1cKJavaThreadDrun6M_v_ (5ecf000, 12f3f0, 4, ff04a000, 12f000, ff1793f0) + 3dc
fed41434 java_start (5ecf000, 54, ff14723c, 116e70, ff04a000, 116c00) + 330
ff2c57f8 _lwp_start (0, 0, 0, 0, 0, 0)
...
...
위 빨간색으로 표시한 부분은 이전 linux에서 확인한 것처럼 동일하게 스택을 가리키는 것을 알수 있습니다.
3. Thread Dump 생성
먼저 Sun HotSpot 계열 Thread Dump에 대해 간단히 살펴 보고 넘어가도록 하겠습니다.
Thread Dump 생성
- Java process를 만든 벤더들이 내부적으로 SIGQUIT에 대한 signal을 catch하여 그 시점의 stack trace를 출력하는 것입니다.
- Unix 계열 (Sun, HP-UX, AIX, Linux 등)
# kill -3 [프로세스 ID]
생성 위치
- Sun 계열 (Sun, HP-UX, Linux 등)의 경우는 Thread dump를 수행하면 STOUT으로 출력됩니다. STOUT은 표준 출력을 말합니다. 표준 출력이란 프로세스가 기본적으로 생성되는 입출력 (FD) 중의 하나입니다. (0:STDIN, 1:STDOUT, 2:STDERR)
WAS의 경우 로그파일에 출력되게 됩니다.
# 참조 Thread 상태 정보
[Sun jdk 1.5]
- initialized : Thread가 초기화 된 상태
- runnable : Thread가 java virtual machine 내에서 수행 중인 상태
- waiting for monitor entry : Thread가 Monitor lock을 획득하기 위해 대기중인 상태
Monitor lock이란 Multi thread 환경에서 thread를 동시 접근하는 것을 막아 database 부하를 줄이거나 thread 병합을 막는 역할을 합니다. 해당 lock은 synchronized 된 object에만 적용 됩니다. 정리하자면, synchronized 된 object를 현재 사용 중인지 아닌지 검사하는 것이 Monitor lock입니다.
- waiting on condition : Thread가 조건 변수(Condition Variable)에 의해 대기 중인 상태
- in object wait() : Thread가 Object.wait()으로 인해 대기 중인 상태
- sleeping : Thread가 I/O등에 의해 대기 중인 SLEEP 상태가 된 경우
[Sun jdk 1.6]
- RUNNABLE : Thread가 java virtual machine 내에서 수행 중인 상태
- BLOCKED : Thread가 Monitor lock을 획득하기 위해 대기중인 상태
- WAITING : Thread가 특정 작업을 위해 다른 Thread를 무기한 대기하는 상태
- TIMED_WAITING : Thread가 특정 작업을 위해 정해진 시가만큼 다른 Thread를 대기하는 상태
- TERMINATED : Thread가 exited 된 상태
위 내용을 기반으로 Thread Dump를 생성합니다.
nrson 10148 9910 0 14:21:39 pts/32 10:40 /usr/jdk1.7.0_10/bin/java -Dserver1 -Xmx1024m -XX:MaxPermSize=128m -server -Xbo
nrson 9910 9909 0 14:11:25 pts/32 0:30 /usr/jdk1.7.0_10/bin/java -server -Xmx512m -Dnodemanager -Xbootclasspath/p:/hom
nrson 11383 9818 0 14:54:53 pts/40 0:00 grep java
nrson 9914 9913 0 14:11:27 pts/32 0:06 /usr/jdk1.7.0_10/bin/java -classpath /home/nrson/jeus7/lib/system/bootstrap.jar
nrson 9879 1 0 14:10:22 pts/32 5:51 /usr/jdk1.7.0_10/bin/java -DadminServer -Xmx1024m -XX:MaxPermSize=128m -server
[nrson@suntest:/home/nrson]$ kill -3 10148
[nrson@suntest:/home/nrson]$
SUNOS(Solaris)의 경우 WAS Server Log 동일 경로의 jvm.log에 생성됩니다.
$JEUS_LOG_HOME/server1/jvm.log
4. Thread Dump 분석
Thread Dump를 편집기로 오픈 한 후 pstack으로 확인한 thread# 85를 HEX로 변환한 결과 값과 nid값을 매칭되는 값을 찾습니다.
85를 변환하면, 0x55이며, 현재 CPU 43%를 잡아 먹는 녀석을 드디어 찾았습니다.
java.lang.Thread.State: RUNNABLE
at jeus_jspwork._700_while_5fjsp._jspService(_700_while_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.servlets.JspServlet.executeServlet(JspServlet.java:134)
at jeus.servlet.servlets.JspServlet.execute(JspServlet.java:74)
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)
어디서 많이 본 형태네요.
LINUX 편과 동일하게 아래와 같이 분석을 진행합니다.
5. 조치
WAS 엔지니어의 입장에서는 JSP 파일(상단의 Stack 정보를 통해 Compiled 된 jsp 파일을 찾을수 있음 - while.jsp)과 Compile java source를 전달하면 완료되지만, 직접 분석을 진행해 보도록 하겠습니다.
JSP 파일과 JAVA 파일을 열어보면 다음과 같습니다.
[while.jsp]
<%
int i=0;
int sum=0;
while (i<=0) {
sum=sum+i;
i=i++;
}
%>
이거만 봐도... 문제가 있죠?? while문이 무한루프가 돌게 작성이 되어 있네요..
다만 단순한 소스가 아니고 Thread Dump 스택의 경우 아래와 같이 Compiled java source 기준으로 line(68)이 표시 되기 때문에 실제로는 java Source를 확인해야 합니다.
java.lang.Thread.State: RUNNABLE
at jeus_jspwork._700_while_5fjsp._jspService(_700_while_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.servlets.JspServlet.executeServlet(JspServlet.java:134)
at jeus.servlet.servlets.JspServlet.execute(JspServlet.java:74)
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_while_5fjsp.java]
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 완료!
자 다음에는 HP-UX 편으로 찾아 오겠습니다.
감사합니다.
# 댓글과 추천은 글쓴이에게 힘이됩니다.!
- 요약
1.prstat 명령을 이용해서 java process의 LWP(Light Weight process) CPU 사용률을 구한다.
% prstat -L -p [PID]
2. pstack 명령어를 이용해서 native thread와 LWP 간의 id mapping을 알아낸다.
(※ 전에 먼저 java process가 lwp로 돌아야되는데, startWebLogic.sh에 LD_LIBRARY_PATH에 /usr/lib/lwp 가 포함되어야 한다.)
% pstack [PID]
3. 1에서 얻은 LWP ID를 pstack log를 통해서 분석해보면 어느 Thread에 mapping되는지를 확인할 수 있다.
여기서는 LWP 8이 Thread 24과 mapping이 되고 있음을 볼 수 있다.
kill -3 [WebLogicPID]를 해서 ThreadDump를 얻어낸다.
Thread dump에서 nid라는 것이 있는데, 2에서 얻어낸 thread id를 16진수로 바꾸면 이값이 nid값과 같다. 즉 2에서 얻어낸 thread 24는 16진수로 0x18이기 때문에, thread dump에서 nid가 0x18인 쓰레드를 찾아서 어떤 작업을하고 있는지를 찾아내면 된다.
'⑥ 네트워크, 운영체제 > ⓞ OS' 카테고리의 다른 글
| [CPU 과점유] AIX 편 (0) | 2018.07.19 |
|---|---|
| [CPU 과점유] HP-UX 편 (0) | 2018.07.19 |
| [CPU 과점유] LINUX 편 (0) | 2018.07.19 |
| [ETC] OS별 TCP Trace Dump 기록 방법 (0) | 2018.06.18 |
| [ETC] OS Hostname Resolution (0) | 2018.06.08 |
- Total
- Today
- Yesterday
- SWA
- 아키텍처
- node.js
- SA
- aws
- OpenStack
- TA
- JEUS7
- Docker
- apache
- API Gateway
- 마이크로서비스
- k8s
- 쿠버네티스
- openstack tenant
- Architecture
- git
- 마이크로서비스 아키텍처
- MSA
- wildfly
- openstack token issue
- JBoss
- Da
- JEUS6
- kubernetes
- webtob
- jeus
- 오픈스택
- nodejs
- aa
| 일 | 월 | 화 | 수 | 목 | 금 | 토 |
|---|---|---|---|---|---|---|
| 1 | 2 | |||||
| 3 | 4 | 5 | 6 | 7 | 8 | 9 |
| 10 | 11 | 12 | 13 | 14 | 15 | 16 |
| 17 | 18 | 19 | 20 | 21 | 22 | 23 |
| 24 | 25 | 26 | 27 | 28 | 29 | 30 |