![[Java] GC log 확인하기(내 가녀린 EC2인스턴스는 정말 GC때문에 죽는게 맞을까? + 갑자기 튀어나온 SerialGC..?)](https://img1.daumcdn.net/thumb/R750x0/?scode=mtistory2&fname=https%3A%2F%2Fblog.kakaocdn.net%2Fdn%2FdMQize%2FbtsHuMFqAvO%2FJvzPyObCk43nMoklaSCxi0%2Fimg.png)
[Java] GC log 확인하기(내 가녀린 EC2인스턴스는 정말 GC때문에 죽는게 맞을까? + 갑자기 튀어나온 SerialGC..?)Web_Backend/Java2024. 5. 20. 22:25
Table of Contents
0. 상황
- 이전 글 에서 말했듯이 aws의 t4g.micro(기존 : t3.micro)라는 작고 가녀린 ec2인스턴스에 docker compose로 spring 어플리케이션을 3개 + nginx까지 구동시키다가, oom kill java 이슈가 발생했다..
(해당 상황을 참여중인 커뮤니티에 공유하니, 모두들 이구동성으로 t3.micro, t4g.micro에 사과하라고 하셨다😅😅)
1. 에러코드 전문
- ec2 인스턴스의 System log에서 발견한 oom 관련 로그는 아래와 같았다.
[69465.875991] systemd invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
[69465.943629] Out of memory: Killed process 2230 (java) total-vm:2823764kB, anon-rss:252396kB, file-rss:0kB, shmem-rss:0kB, UID:0 pgtables:880kB oom_score_adj:0
cf) oom이외에 발생한 시스템 저널 관련 로그와, 네트워크 관련 로그는 아래와 같다.
[37799.885194] systemd-journald[823]: Data hash table of /var/log/journal/ec20eb15684e395496d6f8c93bd51305/system.journal has a fill level at 75.0 (174764 of 233016 items, 100663296 file size, 575 bytes per hash table item), suggesting rotation.
[37799.887086] systemd-journald[823]: /var/log/journal/ec20eb15684e395496d6f8c93bd51305/system.journal: Journal header limits reached or header out-of-date, rotating.
시스템 저널 관련 로그와, oom사이에는 8시간의 간극이 존재해 이번 이슈와 저널의 회전은 관련성이 높지 않다고 판단했다.
[ 42.871465] br-db89533372b4: port 1(vethea56548) entered blocking state
[ 42.872014] br-db89533372b4: port 1(vethea56548) entered disabled state
...
[ 43.441401] IPv6: ADDRCONF(NETDEV_CHANGE): vethea56548: link becomes ready
[ 43.441971] br-db89533372b4: port 1(vethea56548) entered blocking state
[ 43.442511] br-db89533372b4: port 1(vethea56548) entered forwarding state하지만 네트워크 관련 이슈는 oom 이후 약 1.27초 이내에 발생하였음으로, oom직후 네트워크 관련 불안정한 상황이 생긴것으로 의심이 된다.
2. 원인
- 메모리 관련해서 물론 다양한 이슈가 있을 수 있지만... 아직 OS와 메모리 관련 깊은 지식이 있지 않았기에, 우선 내가 추측할수있는 원인들을 하나씩 제거해보는 소거법으로 원인을 찾아보고자 했다.
- 가장 의심이 갔던 부분은 JVM의 Full GC였다. Java 어플리케이션이 3개나 올라가있다는 현황과, cpu 사용량이 일정하게 유지되다가 24시간 이내에 갑작스레 튄다는 부분이 그 이유였다.
3. 해결 과정
1) GC config 확인하기
- 우선은, 정말 GC로 인해서 내 EC2 인스턴스가 뻗는게 맞는지 확인하기 위해 현재 설정된 GC 설정과, 어플리케이션이 구동되는 동안의 GC log를 남겨 확인하고자 했다.
하지만.. 로그를 설정하기 위해, GC 설정값을 확인하던 도중 슬픈 일이 벌어졌다.
[ec2-user@ip-172-31-44-242 apps]$ docker ps -a
CONTAINER ID IMAGE
220c6b64cadb yana94ko/pjt1:prod
c7e50b21f51f yana94ko/pjt2:prod
6ee988a94ff8 yana94ko/pjt3:prod
563ad9398817 nginx:1.23.4
[ec2-user@ip-172-31-44-242 apps]$ docker exec -it 220c6b64cadb sh
sh-4.4# jps
1 war
44 Jps
sh-4.4# jcmd 1 VM.flags
1:
-XX:CICompilerCount=2 -XX:InitialHeapSize=16777216 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=80347136 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=5570560 -XX:NonNMethodCodeHeapSize=5825228 -XX:NonProfiledCodeHeapSize=122916506 -XX:OldSize=11206656 -XX:ProfiledCodeHeapSize=122916506 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC
sh-4.4# exit
exit
[ec2-user@ip-172-31-44-242 apps]$ docker exec -it 220c6b64cadb sh
sh-4.4# jps
1 war
77 Jps
sh-4.4# jcmd 1 VM.flags
1:
-XX:CICompilerCount=2 -XX:InitialHeapSize=16777216 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=80347136 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=5570560 -XX:NonNMethodCodeHeapSize=5825228 -XX:NonProfiledCodeHeapSize=122916506 -XX:OldSize=11206656 -XX:ProfiledCodeHeapSize=122916506 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC
sh-4.4# exit
exit
[ec2-user@ip-172-31-44-242 apps]$ docker exec -it 6ee988a94ff8 sh
sh-4.4# jps
1 war
43 Jps
sh-4.4# jcmd 1 VM.flags
1:
-XX:CICompilerCount=2 -XX:InitialHeapSize=16777216 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=80347136 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=5570560 -XX:NonNMethodCodeHeapSize=5825228 -XX:NonProfiledCodeHeapSize=122916506 -XX:OldSize=11206656 -XX:ProfiledCodeHeapSize=122916506 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC
sh-4.4# exit
....-XX:+UseSerialGC...? ....-XX:+UseSerialGC?????
내 모든 어플리케이션들의 GC는 G1GC가 아닌 Serial GC로 설정되어있었다.. 왜지..?
JDK의 gcConfig를 살펴보면 is_server_class_machine가 true 인 경우 정의된 GC에 따라 G1GC, ParallelGC, SerialGC를 기본GC로 사용하도록 설정되어 있지만, server machine이 아닌 경우에는 default로 SerialGC를 사용하게 되어있었다.
void GCConfig::select_gc_ergonomically() {
if (os::is_server_class_machine()) {
#if INCLUDE_G1GC
FLAG_SET_ERGO_IF_DEFAULT(UseG1GC, true);
#elif INCLUDE_PARALLELGC
FLAG_SET_ERGO_IF_DEFAULT(UseParallelGC, true);
#elif INCLUDE_SERIALGC
FLAG_SET_ERGO_IF_DEFAULT(UseSerialGC, true);
#endif
} else {
#if INCLUDE_SERIALGC
FLAG_SET_ERGO_IF_DEFAULT(UseSerialGC, true);
#endif
}
}
여기서 잠깐, server machine은 뭘까?
JDK의 os.cpp에서 is_server_class_machine()을 살펴보면 아래와 같은데, 결론적으로 요약하면 "프로세서 수가 최소 2개 이상이고, 총 메모리 용량이 2GB 이상(최대 256MB까지의 누락 허용)이며, 프로세서 당 논리적 프로세서 수가 1개 이상인 경우 서버 클래스 머신으로 간주한다"는 내용이었다.
bool os::is_server_class_machine() {
// First check for the early returns
if (NeverActAsServerClassMachine) {
return false;
}
if (AlwaysActAsServerClassMachine) {
return true;
}
// Then actually look at the machine
bool result = false;
const unsigned int server_processors = 2;
const julong server_memory = 2UL * G;
// We seem not to get our full complement of memory.
// We allow some part (1/8?) of the memory to be "missing",
// based on the sizes of DIMMs, and maybe graphics cards.
const julong missing_memory = 256UL * M;
/* Is this a server class machine? */
if ((os::active_processor_count() >= (int)server_processors) &&
(os::physical_memory() >= (server_memory - missing_memory))) {
const unsigned int logical_processors =
VM_Version::logical_processors_per_package();
if (logical_processors > 1) {
const unsigned int physical_packages =
os::active_processor_count() / logical_processors;
if (physical_packages >= server_processors) {
result = true;
}
} else {
result = true;
}
}
return result;
}
이와 관련된 내용은 Java 8의 technotes에서도 찾아 볼 수 있었다.(아직 현재 사용중인 버전인 자바 17버전에 대한 문서는 찾지 못했다. -> 혹시 찾으신 분은 댓글 환영드립니다 엉엉)
결론적으로, 내 작고 소중한 EC2 인스턴스는 태초에는 t3.micro였다가 최근에는 조금 더 저렴하게 서버를 운영하기 위해 t4g.micro 로 변경하였기에 cpu와 프로세서 관련 기준 미달로 default GC가 SerialGC로 설정 된 것 이다!
참고자료 : RedHatDeveloper-Best practices for Java in single-core containers
이에 따라 혹시 GC의 종류에 의한 이슈는 아닐지 또한 확인해봐야 할 필요성이 있다고 생각했다.
2) Serial GC로 돌아갈 인스턴스와, G1GC로 돌아갈 인스턴스 2가지 돌려보기
우선, 기존에 프로젝트를 올려놓은 인스턴스(cassssa)의 이미지를 생성하고 해당 이미지를 통해 새로운 인스턴스(cassssa_g1gc)를 생성했다.
(아, 인스턴스의 name은 원래 yana_playground였는데, 프로젝트를 전부 한곳에 올려놓았다는 소식을 들으신 개발자분께서 모두 다 모여있으니 cassa를 추천해 주셔서, 돌리는 docker image가 4개이니 cassssa로ㅋㅋ 변경해보았다.)
이후 cassssa_g1gc 인스턴스에 접속해 docker compose.yml 파일에서 JAVA_TOOL_OPTIONS을 통해 G1GC를 사용하도록 강제로 설정했다.
//docker compose.yml
pjt1:
image: [dockerhub_username]/pjt1:prod
container_name: pjt1
environment:
AWS_ACCESS_KEY: AAAAA
JAVA_TOOL_OPTIONS: -XX:+UseG1GC
G1GC가 잘적용되었는지 확인 해볼까?
[ec2-user@ip-172-31-35-60 apps]$ docker compose down 0.4s
[ec2-user@ip-172-31-35-60 apps]$ docker compose up -d 0.1s
[ec2-user@ip-172-31-35-60 apps]$ docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
f6016945c900 [dockerhub_username]/pjt1:prod "java -Dspring.profi…" 7 seconds ago Up 6 seconds pjt1
fcc600a4470f [dockerhub_username]/pjt2:prod "java -jar /app.war" 7 seconds ago Up 5 seconds pjt2
3604d02a5697 [dockerhub_username]/pjt3:prod "java -jar /app.war" 7 seconds ago Up 6 seconds pjt3
bcbd191f93c5 nginx:1.23.4 "/docker-entrypoint.…" 7 seconds ago Up 6 seconds 0.0.0.0:80->80/tcp, :::80->80/tcp nginx
[ec2-user@ip-172-31-35-60 apps]$ docker exec -it f6016945c900 sh
sh-4.2# jps
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
1 /app.jar
50 Jps
sh-4.2# jcmd 1 VM.flags
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
1:
-XX:CICompilerCount=2 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=2 -XX:G1EagerReclaimRemSetThreshold=8 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=16777216 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=144703488 -XX:MinHeapDeltaBytes=1048576 -XX:MinHeapSize=8388608 -XX:NonNMethodCodeHeapSize=5826252 -XX:NonProfiledCodeHeapSize=122915994 -XX:ProfiledCodeHeapSize=122915994 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:SoftMaxHeapSize=241172480 -XX:-THPStackMitigation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC
sh-4.2# exit
exit
[ec2-user@ip-172-31-35-60 apps]$ docker exec -it fcc600a4470f sh
sh-4.4# jps
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
1 war
49 Jps
sh-4.4# jcmd 1 VM.flags
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
1:
-XX:CICompilerCount=2 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=2 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=16777216 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=144703488 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=5825228 -XX:NonProfiledCodeHeapSize=122916506 -XX:ProfiledCodeHeapSize=122916506 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC
sh-4.4# exit
exit
[ec2-user@ip-172-31-35-60 apps]$ docker exec -it 3604d02a5697 sh
sh-4.4# jps
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
48 Jps
1 war
sh-4.4# jcmd 1 VM.flags
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC
1:
-XX:CICompilerCount=2 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=2 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=16777216 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=241172480 -XX:MaxNewSize=144703488 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=5825228 -XX:NonProfiledCodeHeapSize=122916506 -XX:ProfiledCodeHeapSize=122916506 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC세 spring 컨테이너 모두에 G1GC가 잘 적용된것을 확인 할 수 있었다.
이제 두 인스턴스를 통해 G1GC 와 Serial GC를 사용할때의 차이점이 발생할지 관찰 할 수 있도록 각각 세팅되었다.
3) 컨테이너 바깥에 GC 로그파일 생성하기
컨테이너가 정말 Full GC로 인해서 죽은걸지 확인하고싶어, GC로그를 파일로 남기고자 했다!
이에 compose.yml 파일에 JAVA_TOOL_OPTIONS에 -Xlog:gc*:file=/logs/gc.log:time 플래그를 추가하고, 컨테이너 내부 /logs에 생성된 로그 파일을 인스턴스의 /gc_logs 폴더 안의 각 프로젝트 폴더에 마운트 해주었다!
//docker compose.yml
pjt1:
image: [dockerhub_username]/pjt1:prod
container_name: pjt1
environment:
AWS_ACCESS_KEY: AAAAA
JAVA_TOOL_OPTIONS: "-XX:+UseG1GC -Xlog:gc*:file=/logs/gc.log:time"
volumes:
- ./gc_logs/pjt1:/logs
pjt2:
image: [dockerhub_username]/pjt2:prod
container_name: pjt2
environment:
AWS_ACCESS_KEY: AAAAA
JAVA_TOOL_OPTIONS: "-XX:+UseG1GC -Xlog:gc*:file=/logs/gc.log:time"
volumes:
- ./gc_logs/pjt2:/logs
pjt3:
image: [dockerhub_username]/pjt3:prod
container_name: pjt3
environment:
AWS_ACCESS_KEY: AAAAA
JAVA_TOOL_OPTIONS: "-XX:+UseG1GC -Xlog:gc*:file=/logs/gc.log:time"
volumes:
- ./gc_logs/pjt3:/logs
이후 각 인스턴스에서 제대로 로그가 생성되고 마운트 되고 있는지 확인했다.
//Serial GC
[ec2-user@ip-172-31-44-242 apps]$ tail -f ./gc_logs/pjt1/gc.log
[2024-05-20T08:44:48.492+0000] GC(82) Tenured: 17747K(25196K)->18944K(25196K)
[2024-05-20T08:44:48.493+0000] GC(82) Metaspace: 41161K(41472K)->41161K(41472K) NonClass: 36144K(36288K)->36144K(36288K) Class: 5017K(5184K)->5017K(5184K)
[2024-05-20T08:44:48.496+0000] GC(82) Pause Young (Allocation Failure) 28M->18M(35M) 9.864ms
[2024-05-20T08:44:48.496+0000] GC(82) User=0.01s Sys=0.00s Real=0.01s
[2024-05-20T08:44:49.066+0000] GC(83) Pause Young (Allocation Failure)
[2024-05-20T08:44:49.071+0000] GC(83) DefNew: 10738K(11456K)->1208K(11456K) Eden: 10240K(10240K)->0K(10240K) From: 498K(1216K)->1208K(1216K)
[2024-05-20T08:44:49.076+0000] GC(83) Tenured: 18944K(25196K)->18944K(25196K)
[2024-05-20T08:44:49.076+0000] GC(83) Metaspace: 42222K(42560K)->42222K(42560K) NonClass: 37062K(37248K)->37062K(37248K) Class: 5159K(5312K)->5159K(5312K)
[2024-05-20T08:44:49.076+0000] GC(83) Pause Young (Allocation Failure) 28M->19M(35M) 9.928ms
[2024-05-20T08:44:49.076+0000] GC(83) User=0.01s Sys=0.00s Real=0.01s
^C
[ec2-user@ip-172-31-44-242 apps]$ tail -f ./gc_logs/pjt2/gc.log
[2024-05-20T08:44:52.739+0000] GC(88) Tenured: 25519K->20752K(27716K)
[2024-05-20T08:44:52.739+0000] GC(88) Metaspace: 44358K->44358K(1089536K)
[2024-05-20T08:44:52.740+0000] GC(88) Pause Full (Metadata GC Threshold) 29M->20M(49M) 82.836ms
[2024-05-20T08:44:52.740+0000] GC(88) User=0.09s Sys=0.00s Real=0.08s
[2024-05-20T08:44:52.995+0000] GC(89) Pause Young (Allocation Failure)
[2024-05-20T08:44:53.001+0000] GC(89) DefNew: 13888K->974K(15616K)
[2024-05-20T08:44:53.001+0000] GC(89) Tenured: 20752K->20752K(34588K)
[2024-05-20T08:44:53.001+0000] GC(89) Metaspace: 45471K->45471K(1091584K)
[2024-05-20T08:44:53.001+0000] GC(89) Pause Young (Allocation Failure) 33M->21M(49M) 6.094ms
[2024-05-20T08:44:53.001+0000] GC(89) User=0.01s Sys=0.00s Real=0.01s
ç^C
[ec2-user@ip-172-31-44-242 apps]$ tail -f ./gc_logs/pjt3/gc.log
[2024-05-20T08:44:51.055+0000] GC(80) Tenured: 19949K->19949K(24260K)
[2024-05-20T08:44:51.055+0000] GC(80) Metaspace: 35354K->35354K(1081344K)
[2024-05-20T08:44:51.055+0000] GC(80) Pause Young (Allocation Failure) 29M->20M(34M) 4.457ms
[2024-05-20T08:44:51.055+0000] GC(80) User=0.01s Sys=0.00s Real=0.00s
[2024-05-20T08:44:51.362+0000] GC(81) Pause Young (Allocation Failure)
[2024-05-20T08:44:51.369+0000] GC(81) DefNew: 10817K->1215K(10944K)
[2024-05-20T08:44:51.369+0000] GC(81) Tenured: 19949K->20681K(24260K)
[2024-05-20T08:44:51.369+0000] GC(81) Metaspace: 36061K->36061K(1081344K)
[2024-05-20T08:44:51.369+0000] GC(81) Pause Young (Allocation Failure) 30M->21M(34M) 6.981ms
[2024-05-20T08:44:51.369+0000] GC(81) User=0.01s Sys=0.00s Real=0.01s
^C//g1gc 인스턴스의 gc log
[ec2-user@ip-172-31-35-60 apps]$ tail -f ./gc_logs/pjt1/gc.log
[2024-05-20T08:49:33.811+0000] GC(34) Post Evacuate Collection Set: 0.6ms
[2024-05-20T08:49:33.811+0000] GC(34) Other: 0.1ms
[2024-05-20T08:49:33.811+0000] GC(34) Eden regions: 21->0(19)
[2024-05-20T08:49:33.811+0000] GC(34) Survivor regions: 2->3(3)
[2024-05-20T08:49:33.811+0000] GC(34) Old regions: 16->17
[2024-05-20T08:49:33.811+0000] GC(34) Archive regions: 2->2
[2024-05-20T08:49:33.811+0000] GC(34) Humongous regions: 0->0
[2024-05-20T08:49:33.811+0000] GC(34) Metaspace: 42265K(42560K)->42265K(42560K) NonClass: 37103K(37248K)->37103K(37248K) Class: 5161K(5312K)->5161K(5312K)
[2024-05-20T08:49:33.811+0000] GC(34) Pause Young (Normal) (G1 Evacuation Pause) 39M->19M(51M) 23.537ms
[2024-05-20T08:49:33.811+0000] GC(34) User=0.01s Sys=0.00s Real=0.03s
^[^C
[ec2-user@ip-172-31-35-60 apps]$ tail -f ./gc_logs/pjt2/gc.log
[2024-05-20T08:49:33.811+0000] GC(34) Post Evacuate Collection Set: 0.6ms
[2024-05-20T08:49:33.811+0000] GC(34) Other: 0.1ms
[2024-05-20T08:49:33.811+0000] GC(34) Eden regions: 21->0(19)
[2024-05-20T08:49:33.811+0000] GC(34) Survivor regions: 2->3(3)
[2024-05-20T08:49:33.811+0000] GC(34) Old regions: 16->17
[2024-05-20T08:49:33.811+0000] GC(34) Archive regions: 2->2
[2024-05-20T08:49:33.811+0000] GC(34) Humongous regions: 0->0
[2024-05-20T08:49:33.811+0000] GC(34) Metaspace: 42265K(42560K)->42265K(42560K) NonClass: 37103K(37248K)->37103K(37248K) Class: 5161K(5312K)->5161K(5312K)
[2024-05-20T08:49:33.811+0000] GC(34) Pause Young (Normal) (G1 Evacuation Pause) 39M->19M(51M) 23.537ms
[2024-05-20T08:49:33.811+0000] GC(34) User=0.01s Sys=0.00s Real=0.03s
^[^C
[ec2-user@ip-172-31-35-60 apps]$ tail -f ./gc_logs/pjt3/gc.log
[2024-05-20T08:49:33.811+0000] GC(34) Post Evacuate Collection Set: 0.6ms
[2024-05-20T08:49:33.811+0000] GC(34) Other: 0.1ms
[2024-05-20T08:49:33.811+0000] GC(34) Eden regions: 21->0(19)
[2024-05-20T08:49:33.811+0000] GC(34) Survivor regions: 2->3(3)
[2024-05-20T08:49:33.811+0000] GC(34) Old regions: 16->17
[2024-05-20T08:49:33.811+0000] GC(34) Archive regions: 2->2
[2024-05-20T08:49:33.811+0000] GC(34) Humongous regions: 0->0
[2024-05-20T08:49:33.811+0000] GC(34) Metaspace: 42265K(42560K)->42265K(42560K) NonClass: 37103K(37248K)->37103K(37248K) Class: 5161K(5312K)->5161K(5312K)
[2024-05-20T08:49:33.811+0000] GC(34) Pause Young (Normal) (G1 Evacuation Pause) 39M->19M(51M) 23.537ms
[2024-05-20T08:49:33.811+0000] GC(34) User=0.01s Sys=0.00s Real=0.03s
성공적으로 GC 로그를 남기는데에 성공했다!
4) 트래픽을 강제로 발생시켜보기 or 동일한 상황을 유발하기 위해 24시간동안 인스턴스 방치하기?
우선 트래픽을 강제로 발생시켜서 확인해본 뒤 동일한 현상이 나타나지 않는다면 인스턴스를 방치해보고자 했다.
domain으로 포트포워딩 해놓은 cassssa 인스턴스와 달리 포트를 직접 사용해야하는 casssa_g1gc서버의 트래픽을 강제로 발생시키기 위해서는 nginx config와 docker compose.yml의 nginx port 설정을 바꿔주어야 했다.
자세한 내용은 여기에 ⬇️
더보기
우선 nginx의 config에서 기존에 server_name만으로 포워딩을 해주던 것을 각 서비스의 포트를 직접 listen 하도록 설정했다.
server{
listen 8001; # 80-> 8001로 변경
server_name pjt1.com;
location / {
proxy_pass http://pjt1.com:8001;
proxy_set_header host $host;
}
}
server{
listen 8002; # 80-> 8002로 변경
server_name pjt2.com;
location / {
proxy_pass http://pjt2.com:8002;
proxy_set_header host $host;
}
}
server{
listen 8003; # 80-> 8003로 변경
server_name pjt3.com;
location / {
proxy_pass http://pjt3.com:8003;
proxy_set_header host $host;
}
}
다음으로는 nginx또한 docker로 띄워놓은 상황이기에, docker compose.yml 파일에서 nginx 컨테이너가 host의 80포트 뿐 아니라 8001, 8002, 8003포트 또한 매핑하도록 설정했다.
services:
nginx:
image: nginx:1.23.4
container_name: nginx
ports:
- 80:80
- 8025:8025
- 8021:8021
- 8091:8091
volumes:
- ./nginx/nginx.conf:/etc/nginx/nginx.conf
- ./nginx/conf.d/default.conf:/etc/nginx/conf.d/default.conf
- ./nginx/access.log:/var/log/nginx/access.log
- ./nginx/error.log:/var/log/nginx/error.log
마지막으로 AWS 인스턴스의 보안그룹에서 임시로 인바운드 규칙에서 8001, 8002, 8003포트를 열어줌으로써 강제로 트래픽을 발생시킬 준비를 완료했다.
빠르게 트래픽을 생성하기 위해 K6를 활용했다.
// kg_g1gc_test.js 파일 생성
import http from 'k6/http';
import { check, sleep } from 'k6';
export let options = {
stages: [
{ duration: '1m', target: 4000 },
{ duration: '2m', target: 8000 },
{ duration: '3m', target: 9000 },
{ duration: '1m', target: 0 },
],
};
const hosts = [
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8001',
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8002',
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8003'
];
export default function () {
const host = hosts[__VU % hosts.length];
let res = http.get(host);
check(res, {
'status is 200': (r) => r.status === 200,
});
sleep(1); // Sleep for 1 second between requests
}
// kg_serial_test.js 파일 생성
import http from 'k6/http';
import { check, sleep } from 'k6';
export let options = {
stages: [
{ duration: '1m', target: 4000 },
{ duration: '2m', target: 8000 },
{ duration: '3m', target: 9000 },
{ duration: '1m', target: 0 },
],
};
const hosts = [
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8001',
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8002',
'http://[g1gc 인스턴스 퍼블릭 IPv4]:8003'
];
export default function () {
const host = hosts[__VU % hosts.length];
let res = http.get(host);
check(res, {
'status is 200': (r) => r.status === 200,
});
sleep(1); // Sleep for 1 second between requests
}
K6로 요청을 날려보기 시작했다
// k6로 요청 시작
k6 run k6_g1gc_test.js & k6 run k6_serial_test.js
첫 번째로 Serial GC를 사용중인 casssa의 K6 임시 부하테스트 결과는 아래와 같았다.
//Serial GC 인스턴스 결과
✗ status is 200
↳ 0% — ✓ 1848 / ✗ 233022
checks.........................: 0.78% ✓ 1848 ✗ 233022
data_received..................: 86 MB 190 kB/s
data_sent......................: 19 MB 41 kB/s
http_req_blocked...............: avg=633.36µs min=0s med=7µs max=213.64ms p(90)=13µs p(95)=251.54µs
http_req_connecting............: avg=611.88µs min=0s med=0s max=212.41ms p(90)=0s p(95)=0s
http_req_duration..............: avg=10.43s min=9.78ms med=10.01s max=1m0s p(90)=10.02s p(95)=10.03s
{ expected_response:true }...: avg=180.03ms min=9.78ms med=18.99ms max=24.57s p(90)=496.56ms p(95)=828.62ms
http_req_failed................: 99.21% ✓ 233022 ✗ 1848
http_req_receiving.............: avg=1.04ms min=0s med=45µs max=57.82s p(90)=111µs p(95)=181µs
http_req_sending...............: avg=67.78µs min=2µs med=19µs max=27.83ms p(90)=65µs p(95)=169µs
http_req_tls_handshaking.......: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
http_req_waiting...............: avg=10.43s min=9.41ms med=10.01s max=1m0s p(90)=10.02s p(95)=10.03s
http_reqs......................: 234870 521.908439/s
iteration_duration.............: avg=11.43s min=1.01s med=11.01s max=1m1s p(90)=11.03s p(95)=11.04s
iterations.....................: 234865 521.897329/s
vus............................: 1 min=1 max=8998
vus_max........................: 9000 min=9000 max=9000
running (7m30.0s), 0000/9000 VUs, 234865 complete and 188 interrupted iterations
default ✓ [======================================] 0000/9000 VUs 7m0s
다음으로 G1GC를 사용중인 casssa_g1gc의 K6 임시 부하테스트 결과는 아래와 같았다.
// g1gc 인스턴스 결과
✗ status is 200
↳ 2% — ✓ 2706 / ✗ 87528
checks.........................: 2.99% ✓ 2706 ✗ 87528
data_received..................: 29 MB 65 kB/s
data_sent......................: 411 kB 915 B/s
http_req_blocked...............: avg=2.56ms min=0s med=0s max=19.01s p(90)=0s p(95)=3µs
http_req_connecting............: avg=2.56ms min=0s med=0s max=19.01s p(90)=0s p(95)=0s
http_req_duration..............: avg=1.44s min=0s med=0s max=1m0s p(90)=0s p(95)=11.08ms
{ expected_response:true }...: avg=148.19ms min=7ms med=46.03ms max=52.99s p(90)=275.45ms p(95)=703.64ms
http_req_failed................: 97.00% ✓ 87544 ✗ 2706
http_req_receiving.............: avg=1.8ms min=0s med=0s max=58.52s p(90)=0s p(95)=0s
http_req_sending...............: avg=4.28µs min=0s med=0s max=9.21ms p(90)=0s p(95)=11µs
http_req_tls_handshaking.......: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
http_req_waiting...............: avg=1.44s min=0s med=0s max=1m0s p(90)=0s p(95)=10.88ms
http_reqs......................: 90250 200.755581/s
iteration_duration.............: avg=30.83s min=1s med=31s max=1m1s p(90)=31.02s p(95)=31.12s
iterations.....................: 90004 200.208369/s
vus............................: 3 min=3 max=9000
vus_max........................: 9000 min=9000 max=9000
running (7m29.6s), 0000/9000 VUs, 90004 complete and 253 interrupted iterations
default ✓ [======================================] 0000/9000 VUs 7m0s
신나서 시스템 로그를 확인하러갔는데... 어디갔지..?
4. 결과
너무나 당연하게도 Serial GC보다는 성공한 요청이 약 1000건정도 늘어나기는 했지만 G1GC로의 변경만으로는 문제가 해결되었을것이라고 확신할 수 없었다(당연히 해결되지 않았겠지만). 현재는 G1GC로의 변경이 얼마나 어플리케이션 운영에 영향을 주는지 제대로 확인해보고싶어 기존처럼 docker compose 로 서비스들을 올려놓은 뒤 대기중에 있다.(2024.05.20 22:00).
어플리케이션의 정상 구동을 위해 추후로 확인해볼 사항은, "JVM 힙메모리 제한 설정하기" 와 "SWAP 메모리 지정하기"가 있(으며 당연하게도 서버 스케일업도 방법에 있지만 최대한 여러가지 공부를 마쳐본 뒤에 설정해보고자 한)다.(진행중)
[JVM] JVM Heap Memory size, JVM 힙(heap) 크기 조정 과 [aws, memory] Ubuntu swap memory 설정하기(feat. aws ec2) 는 각각 해당 글에서 자세하게 다뤄보고자 한다..! (아직 작성되어있지 않음.)
5. 추후 학습
이번 GC관련 삽질을 참여중인 개발자 네트워크에도 공유해 많은 분들이 살펴보면 좋을 부분들과 글들을 안내해주셨는데, 그중에서 최근 Reactor netty관련 업무를 보고계신 개발자분께서 토스의 Reactor netty Memory 이슈 관련 기술블로그를 보내주셨다.
- 해당 글에서 토스는 메모리 할당에 드는 오버헤드를 최대한 줄이기 위해 -XX:+AlwaysPreTouch JVM 옵션을 사용하고 있다는 사실을 알게되어 해당 옵션에 대해서도 공부를 해볼까 한다.
- 물론 Reactor netty 관련해서도 추가적으로 학습을 해보고싶다(언젠가 내게도 사용할 이유가 생기지 않을까..?)
- 마지막으로 토스에서는 컨테이너가 OOMKilled로 죽었다는 것은 JVM heap 영역 문제일 확률이 낮다고 보셨으며, Residential Set Size(RSS)관련 로그를 살펴보셨다고 하셨는데 JVM heap 영역이 아닌 native 영역의 메모리관련 이슈와 RSS 사이에는 어떠한 연관관계가 있으며 어떠한 방식으로 트러블 슈팅을 하신건지 netty 학습시에 함께 공부해보면 좋을 것같다.
- 헤헤 추가적으로 OOM Kill과 컨테이너(k8s)에서의 OOMKilled은 주체가 다르다는 피드백을 받아, 컨테이너 환경에서의 OOM에 대해서도 알아보면 좋을 것 같다.(공부할게 정말 끝이 없구나!)
'Web_Backend > Java' 카테고리의 다른 글
@Yanako :: Yana's coding story였는데요, 우당탕탕 개발일지가 맞는것같
야나의 코딩 일기장 :) #코딩블로그 #기술블로그 #코딩 #조금씩,꾸준히
포스팅이 좋았다면 "좋아요❤️" 또는 "구독👍🏻" 해주세요!