20170908 tech day-9th-재미없는 java runtime process 디버그-김성중
47
재미없는 Java Runtime Process 디버그 2017년 9월 8일 김성중 (개발 3팀) 디버그, 디버깅: - 컴퓨터 프로그램의 정확성이나 논리적인 오류(버그)를 찾아내는 테스트 과정 재미없는 Java Runtime Process 디버그 - 실행중인 프로세스를 분석해야 하는 상황이 발생 재미없는 상황
Transcript of 20170908 tech day-9th-재미없는 java runtime process 디버그-김성중
재미없는Java Runtime Process
디버그
2017년 9월 8일
김성중
(개발 3팀)
디버그, 디버깅:- 컴퓨터 프로그램의 정확성이나 논리적인 오류(버그)를 찾아내는 테스트 과정 재미없는 Java Runtime Process 디버그- 실행중인 프로세스를 분석해야 하는 상황이 발생 재미없는 상황
목차
2
1. 분석 대상 프로세스 개요
1.1 시스템 구성도
1.2 로그 수집/분석 흐름도
1.3 처리 작업 및 데이터
2. 멈춤 현상
2.1 실행 후 정상 종료되어야 할 프로세스의 멈춤 현상 발생
3. Java 프로세스 디버그
3.1 프로세스란?
3.2 Java 명령 도구
3.3 Memory Analyzer
3.4 주의 사항
0. 시놉시스 – Profiling 도구 및 디버깅 도구들
0.1 Java Mission Control
0.2 Visual VM
0.3 JDWP
0. 시놉시스
• 0.1 Java Mission Control• JDK 설치 시
• Oracle
• 유료화
• 0.2 VisualVM• JDK 1.7 이상 필요
• Target jre 1.4 이상
• 경량의 프로파일 도구
• LICENSE: GPLv2 + CE
• PROJECT OWNERS:
• Jiri Sedlacek, [email protected]
• Tomas Hurka, [email protected]
• 0.3 JDWP(Java Debug Wire Protocol)• JVM & Debugger간 통신 protocol
• 가장 편하고 재미있는(?) 디버깅
• 대표적인 예) eclipse debug
0.1 Java Mission Control
• File / Connect
0.1 Java Mission Control
• Memory / Allocation in New TLAB / Allocation by Class
0.1 Java Mission Control
• Memory / Allocation in New TLAB / Allocation by Thread
0.2 Visual VM
• java process 연결• heap, thread 정보 조회
0.2 Visual VM
• class instance 목록
Visual VM
• instance 별 속성 확인
0.2 Visual VM
• snapshot 찍기
0.2 Visual VM
• snapshot 간 비교
0.2 Visual VM
• snapshot 간 비교: 추가/삭제된 Object 목록(메모리 릭 조회)
0.2 Visual VM
• Thread 별 Object 목록
0.3 JDWP(Java Debug Wire Protocol)
0.3 JDWP(Java Debug Wire Protocol)
• java -agentlib:jdwp=transport=dt_socket,address=0.0.0.0:8000,server=y,suspend=y -D... -cp … net.lguplus….Main
• java -agentlib:jdwp=transport=dt_socket,address=localhost:8000,server=y,suspend=n -D... -cp … net.lguplus….Main
• suspend=y• java 프로세스 실행 직후 대기, Debugger가 연결된 후 main method가 실행.
1. 분석 대상 프로세스 개요1.1 시스템 구성도
1.2 로그 수집/분석 흐름도
1.3 처리 작업 및 데이터
16
1.1 시스템 구성도
17
로그 수집/분석 서버
로그 수집/분석 서버
저장소
10분, 분석 결과 전송
10분, 분석 결과 전송
암호화 데이터
HTTPS
HTTP
Disk
1.2 로그 수집/분석 흐름도(1/2)
Collector( java,
Grizzly - 443, 8443)Analyzer
( java, multicore)
Disk
1
2
3
load 로그4
로그 삭제(crontab)
Sender( java, sftp)
HDD
Monitor( java, inotify)
5
6
7
8
10
6
8
7
분석 누락 파일 처리(crontab)
실행
수집 로그 저장(port 당 1 ~ 10개)
수집 로그 백업
분석 프로세스 실행(최대 20개)
File 모니터링
분석 결과 전송 프로세스 실행 (최대 20개)
분석 결과 백업
로그 분석 결과 저장
분석 결과 백업
분석 결과 전송
분석 프로세스
1.2 로그 수집/분석 흐름도(2/2)
Queue(inQueue)
LogParser파일
ReaderLogParser
LogParser
…
LogParser
Queue(outQueue)
파일Writer
전송 프로세스• jcsh 모듈을 이용한 sftp 전송
파일감시/실행 파일
감시/실행
저장소
모니터 프로세스• inotify를 이용한 파일 모니터링(IN_WRITE_CLOSE)
WatchService 의 한계: 파일 저장 시 ENTRY_MODIFY 이벤트가 1 ~ 수 회 발생파일 저장이 완료됨을 특정할 수 없음
Linux system call 을 JNI 로 작성• 로그파일 별 분석 프로세스 실행 관리
분석 프로세스는 Multi-Core 실행
1.3 처리 작업 및 데이터
• System log 수집기• line 당 평균 약 350개• 1시간 4Gb• HTTPS(443, 8443)
• 포트 당 1 ~ 10개 균등 분할 저장(총 20개)
• 약 150 ~ 180만 대 단말이 3시간마다 POST 방식으로 요청
• 분석기• 모니터 프로세스에 의해 매 분마다 20개의 분석기 실행 시
• 각 분석기 는 31개의 스래드 실행• file loader 1개, file writer 1개,
• optional : failure writer 1개, ignore writer 1개, malformed writer 1개
• log parser 25 ~ 28 개 스래드
• main thread
1140.773e.ccdf^^2017-06-11 07:02:11^^20170604170924 무선 단말 접속 해제 [09:11:f2:af:a1:a2] 단말to AP [code:RC01], AP_SSID_5G (5GHz)|20170604171659 … | … | … | …
2. 멈춤 현상2.1 실행 후 정상 종료되어야 할 프로세스의 멈춤 현상 발생
21
2.1 실행 후 정상 종료되어야 할 프로세스의 멈춤 현상 발생
• 분석기는 N개의 프로세스가 매 10 분마다 실행되어 종료되어야 함.• 전체 프로세스가 약 2 ~ 6시간 정도 실행 중 약 1 ~ 3(또는 그 이상?)개의 QLCSysAnalyzer가 종
료하지 못하고 멈춤.
• 분석기 프로세스는 모니터 프로세스가 실행하는 프로세스로 로그만 확인 할 수 있음
• 단독 프로세스로 실행 시 멈춤 현상 발생하지 않음.
• 멈춤 현상 발생 시 기록 되는 로그 없음.
• 멈춤 현상 발생 시 최종 로그 확인해 보면 정상 로그 기록.
• child process로 실행되니 디버거로 디버깅 할 수도 없는 상황인데 문제를 어떻게 찾을까?
3. Java 프로세스 디버그3.1 프로세스란(프로세스, 스택)?
3.2 Java 명령 도구
3.3 Memory Analyzer
3.4 주의 사항
23
3.1 프로세스란? - 개요
• 프로그램(Program)• 보조 기억장치에 저장되어 있는 실행 가능한 형태의 파일
• 프로세스(Process)• 프로그램이 메모리에 적재되어 실행되는 작업의 단위
• 스레드(Thread)• 프로세스 내 실행되는 흐름의 단위
• 1개의 프로세스는 최소 1개의 스레드로 구성
• 다중 스레드는 1개의 코어(core) 또는 여러 개의 코어에서 실행
• 각 스레드 별 작업 공간• Stack
• 로컬 변수 및 인자(parameter)는 stack에 저장
• 컴파일 시점에 기억 장소의 크기는 확정
• new, malloc(C언어) 등에 의한 할당은 실행 시에, heap에 저장 공간 할당되지만 변수는 stack에 저장
• 함수(function) 또는 메소드(method) 호출 시 마다 Stack에 누적(call stack)
• 현재 실행 위치에 대한 stack – 활성레코드
• Exception• 실행 중에 발생할 수 있는 예기치 않은 사건
• Exception 핸들링 위치까지 call stack 은 무시
3.1 프로세스란? – call stack
int argc;char carray[128];
String name;
int b
int a
byte barray[1024]String str;
int a;int b;
thread.run()catch (Exception e)
a.method1()
b.method1()catch (IOException e)
c.method2()
d.method1()
d.method2()IOException
Exception
call stack
call
call
call
call
call
return
return
return
return
return
3.2 Java 명령 도구 - jstack
• 프로세스 PID 확인• # ps –ef|grep tomcat
root 205787 1 2 18:53 ? 00:00:49 /usr/lib/jvm/java-8-oracle/bin/java -Djava.util.logging.config.file=/root/projects/bdp/apache-tomcat-8.5.11/conf/logging.properties –D…
• 프로세스의 스래드 목록 확인• # ps -o "ppid,pid,tid,pcpu,pmem,command" -Lp 205787
PPID PID TID %CPU %MEM COMMAND…1 205787 208964 0.0 0.5 /usr/lib/jvm/java-8-oracle/bin/java -Djava.util.logging.config.file=/root/projects/bdp/apache-tomcat-8.5.11/conf/logging.properties -Djava.util.logging.m1 205787 208973 0.0 0.5 /usr/lib/jvm/java-8-oracle/bin/java -Djava.util.logging.config.file=/root/projects/bdp/apache-tomcat-8.5.11/conf/logging.properties -Djava.util.logging.m1 205787 237602 0.0 0.5 /usr/lib/jvm/java-8-oracle/bin/java -Djava.util.logging.config.file=/root/projects/bdp/apache-tomcat-8.5.11/conf/logging.properties -Djava.util.logging.m
• JAVA 프로세스의 스래드별 call statk 을 수집• # jstack -l 205787 > call_stack.txt
# vi tomcat_stack.txt"http-nio-8080-exec-195" #232 daemon prio=5 os_prio=0 tid=0x00007fdb740b3000 nid=0x3304d waiting on condition [0x00007fd93f4f3000]
java.lang.Thread.State: WAITING (parking)at sun.misc.Unsafe.park(Native Method)- parking to wait for <0x00000005c9bfd060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
0x3304d 208973
3.2 Java 명령 도구 – jcmd, jmap
• 프로세스 PID 확인• # ps -ef | grep QLCSyslogAnalyzer
root 136899 136875 99 13:21 pts/12 00:00:20 java -DQLC_HOME=/home/socialcare/projects/QLC/dist -DLOG_INFIX=443 -DANALYZER_NUMBER=01 -jar /home/socialcare/projects/QLC/dist/lib/QLCSyslogAnalyzer-1.0.0.jar -c /home/socialcare/projects/QLC/dist/conf/config.json -p /home/socialcare/projects/QLC/dist/conf/qlcsysanal.properties -i/home/socialcare/projects/QLC/dist/aplog/APSyslog_QLC01_443_01_20170731132100.log -o /home/socialcare/projects/QLC/dist/output/success -f /home/socialcare/projects/QLC/dist/output/failure
• Java 프로세스 GC(garbage collection) 강제 실행• # jcmd 136899 GC.run
• https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr006.html
• Java 프로세스 Heap dump• # jmap -dump:format=b,file=QLCSyslogAnalyzer.hprof 136899
• http://docs.oracle.com/javase/7/docs/technotes/tools/share/jmap.html
• download “QLCSyslogAnalyzer.hprof”
# jmap -dump:live,format=b,file=QLCSyslogAnalyzer.hprof 136899
Dumps the Java heap in hprof binary format to filename. The live suboption is optional. Ifspecified, only the live objects in the heap are dumped. To browse the heap dump, you canuse jhat (Java Heap Analysis Tool) to read the generated file.
3.3 Memory Analyzer
• Memory Analyzer• http://www.eclipse.org/mat
• http://www.eclipse.org/mat/downloads.php
3.3 Memory Analyzer
3.3 Memory Analyzer
3.3 Memory Analyzer
• Java Object List 분석
3.3 Memory Analyzer
• 필요에 따라 class, package 별 그룹
3.3 Memory Analyzer
• heap을 가장 많이 사용하는 object가 문제와 관련이 높음.
3.3 Memory Analyzer – with incoming references
• ConcurrentLinkedQueue가 대부분의 메모리를 사용 중• readerparser thread 간 데이터 전달 목적으로 사용
3.3 Memory Analyzer – with incoming references
• ConcurrentLinkedQueue를 참조하는 Object 목록
3.3 Memory Analyzer – with outgoing references
• net.lguplus.bdp.qlc.loganalyzer.thread.FileReaderCallable 클래스
3.3 Memory Analyzer – with outgoing references
• class loader가 로딩한 class 정보만
3.3 Memory Analyzer – with outgoing references
• FileWriterCallable가 참조하는 objects 목록
3.3 Memory Analyzer – with outgoing references
• Live objects: class instance
Live object에 대하여• static 정보• attribute 정보(value 포함)• class 계층 구조등을 확인 가능.
Class 의 Live object 목록 및 class 정보
3.3 Memory Analyzer – Thread
• 어떤 thread에 문제가 있는지 확인이 필요
• Thread의 실행 위치를 확인하기 위하여 call stack을 분석
3.3 Memory Analyzer – Thread 분석
• FileReader Thread는 종료되었음을 확인• 파일을 모두 읽고 정상 종료 되었을 것 이거나
• Exception 발생 후 비정상 종료되었을 것으로 추측
3.3 Memory Analyzer – Thread 분석
• 로그 분석 thread는 아직 실행 중이며, inputFinished=true• FileReader thread는 정상 종료되었음을 확인함.
3.3 Memory Analyzer – Thread 분석
• outQueue 의 개수가 30000개 이상• 현재 스래드는 outQueue가 비워지기를 기다리고 있음
• 그렇다면, outQueue가 비워지지 않는다?• outQueue를 비우는 FileWriter Thread에 문제가 예상
3.3 Memory Analyzer – Thread 분석
• 이런!!! 아직 분석 thread가 종료되지 않았는데 Writer Thread는 이미 종료.
• 더 이상 진행 불가, FileWriter에 문제가 있음이 파악되었으니• FileWriterCallable 클래스의 비정상 종료될 만한 코드 분석 및 로그 기록
IOException: No disk space
3.4 주의 사항
• 힙 히스토그램을 실행하면 어플리케이션에 부하가 발생• 어플리케이션에서 통계정보 생성 때문
• 정상 실행 중인 서비스 프로세스에서는 사용하지 말 것• 인생은 모험이다.
10월 13일
개발2팀 대리
47
끝
㈜ 유미테크 (Ubiquitous Media Technology Co., Ltd.)
대전시 유성구 가정로 218번 융합기술연구생산센터 703호
042-867-4220~3 [email protected]
