GC 로그 찍어서 분석해보기

GPT의 도움을 받아 공부하였다.

 

먼저 GC 로그를 찍기 위해 vm 옵션에 아래의 값을 추가하자

// 초기메모리, 최대 메모리 , 로그 옵션
-Xms512m -Xmx512m -Xlog:gc*:file=gc.log

IntelliJ vm option gc log 추가

 

 

 

 

Mixed GC를 경험해보자 

import java.util.ArrayList;
import java.util.List;

public class MemoryLeakTest {
    private static final List<byte[]> LEAK = new ArrayList<>();

    public static void main(String[] args) throws Exception {
        System.out.println("Start Leak Test");
        long l = System.currentTimeMillis();

        while (true) {
            byte[] data = new byte[1024 * 256]; // 256KB
            LEAK.add(data); // 참조 유지 → Old 영역 계속 증가

            Thread.sleep(50);
            long e = System.currentTimeMillis();

            // 30초 지났으면 한 번에 참조 해제
            if (e - l >= 30_000) {
                System.out.println("CLEAR at " + (e - l) + " ms");
                l = e;
                LEAK.clear(); // 리스트에 담긴 참조 제거 → GC 대상
            }
        }
    }
}

 

 

어느정도 시간이 지나면 종료하고 로그를 확인한다.

자신의 프로젝트 폴더 내에 gc.log 파일이 생성되었을 것이다.

[0.009s][info][gc] Using G1                                 // 사용 GC
[0.013s][info][gc,init] Version: 17.0.9+11-LTS-201 (release) // JAVA VERSION
[0.013s][info][gc,init] CPUs: 12 total, 12 available	    // CPU INFO
[0.013s][info][gc,init] Memory: 32618M					    // HOST MEMORY
[0.013s][info][gc,init] Large Page Support: Disabled	
[0.013s][info][gc,init] NUMA Support: Disabled
[0.013s][info][gc,init] Compressed Oops: Enabled (32-bit)
[0.013s][info][gc,init] Heap Region Size: 1M				// HEAP의 Region 사이즈 
[0.013s][info][gc,init] Heap Min Capacity: 512M				// 최소 Heap 메모리 용량
[0.013s][info][gc,init] Heap Initial Capacity: 512M			// 초기 Heap 메모리 용량
[0.013s][info][gc,init] Heap Max Capacity: 512M				// 최대 Heap 메모리 용량
[0.013s][info][gc,init] Pre-touch: Disabled					// Pre-Totch 기능 
[0.013s][info][gc,init] Parallel Workers: 10				// 병렬 워커 (쓰레드) 10개
[0.013s][info][gc,init] Concurrent Workers: 3				// 동시 작업 쓰레드 3개
[0.013s][info][gc,init] Concurrent Refinement Workers: 10   // Remembered Set 업데이트용 스레드
[0.013s][info][gc,init] Periodic GC: Disabled				// 주기적 GC 비활성화

 

Per-touch 

JVM이 시작시 힙 전체를 처음부터 모든 OS 페이지(보통 4KB) 단위에 미리 한 번씩 접근

이로 page fault를 시작 시점에 전부 발생시켜 힙 전체가 이미 물리 메모리에 연결된 상태로 서비스를 시작한다.

런타임에서 GC가 page fault로 끊기는 일이 없어진다.

키면 좋은 옵션인듯 하다.

 

-XX:+AlwaysPreTouch

옵션

 

 

[39.828s][info][gc,start    ] GC(6) Pause Young (Normal) (G1 Evacuation Pause)
[39.828s][info][gc,task     ] GC(6) Using 10 workers of 10 for evacuation
[39.834s][info][gc,phases   ] GC(6)   Pre Evacuate Collection Set: 0.1ms
[39.834s][info][gc,phases   ] GC(6)   Merge Heap Roots: 0.0ms
[39.834s][info][gc,phases   ] GC(6)   Evacuate Collection Set: 5.6ms
[39.834s][info][gc,phases   ] GC(6)   Post Evacuate Collection Set: 0.2ms
[39.835s][info][gc,phases   ] GC(6)   Other: 0.1ms
[39.835s][info][gc,heap     ] GC(6) Eden regions: 67->0(81)
[39.835s][info][gc,heap     ] GC(6) Survivor regions: 8->10(10)
[39.835s][info][gc,heap     ] GC(6) Old regions: 186->240
[39.835s][info][gc,heap     ] GC(6) Archive regions: 0->0
[39.835s][info][gc,heap     ] GC(6) Humongous regions: 0->0
[39.835s][info][gc,metaspace] GC(6) Metaspace: 785K(896K)->785K(896K) NonClass: 723K(768K)->723K(768K) Class: 62K(128K)->62K(128K)
[39.835s][info][gc          ] GC(6) Pause Young (Normal) (G1 Evacuation Pause) 260M->249M(512M) 6.204ms
[39.835s][info][gc,cpu      ] GC(6) User=0.00s Sys=0.00s Real=0.01s
[52.120s][info][gc,start    ] GC(7) Pause Young (Concurrent Start) (G1 Evacuation Pause)
[52.120s][info][gc,task     ] GC(7) Using 10 workers of 10 for evacuation
[52.130s][info][gc,phases   ] GC(7)   Pre Evacuate Collection Set: 0.1ms
[52.130s][info][gc,phases   ] GC(7)   Merge Heap Roots: 0.0ms
[52.130s][info][gc,phases   ] GC(7)   Evacuate Collection Set: 9.7ms
[52.130s][info][gc,phases   ] GC(7)   Post Evacuate Collection Set: 0.3ms
[52.130s][info][gc,phases   ] GC(7)   Other: 0.2ms
[52.130s][info][gc,heap     ] GC(7) Eden regions: 81->0(45)
[52.130s][info][gc,heap     ] GC(7) Survivor regions: 10->12(12)
[52.130s][info][gc,heap     ] GC(7) Old regions: 240->319
[52.130s][info][gc,heap     ] GC(7) Archive regions: 0->0
[52.130s][info][gc,heap     ] GC(7) Humongous regions: 0->0
[52.130s][info][gc,metaspace] GC(7) Metaspace: 785K(896K)->785K(896K) NonClass: 723K(768K)->723K(768K) Class: 62K(128K)->62K(128K)
[52.130s][info][gc          ] GC(7) Pause Young (Concurrent Start) (G1 Evacuation Pause) 330M->330M(512M) 10.411ms
[52.130s][info][gc,cpu      ] GC(7) User=0.02s Sys=0.00s Real=0.01s
[52.130s][info][gc          ] GC(8) Concurrent Mark Cycle
[52.130s][info][gc,marking  ] GC(8) Concurrent Clear Claimed Marks
[52.130s][info][gc,marking  ] GC(8) Concurrent Clear Claimed Marks 0.018ms
[52.130s][info][gc,marking  ] GC(8) Concurrent Scan Root Regions
[52.130s][info][gc,marking  ] GC(8) Concurrent Scan Root Regions 0.205ms
[52.130s][info][gc,marking  ] GC(8) Concurrent Mark
[52.131s][info][gc,marking  ] GC(8) Concurrent Mark From Roots
[52.131s][info][gc,task     ] GC(8) Using 3 workers of 3 for marking
[52.131s][info][gc,marking  ] GC(8) Concurrent Mark From Roots 0.893ms
[52.131s][info][gc,marking  ] GC(8) Concurrent Preclean
[52.132s][info][gc,marking  ] GC(8) Concurrent Preclean 0.077ms
[52.132s][info][gc,start    ] GC(8) Pause Remark
[52.133s][info][gc          ] GC(8) Pause Remark 330M->165M(512M) 0.949ms
[52.133s][info][gc,cpu      ] GC(8) User=0.00s Sys=0.00s Real=0.00s
[52.133s][info][gc,marking  ] GC(8) Concurrent Mark 2.183ms
[52.133s][info][gc,marking  ] GC(8) Concurrent Rebuild Remembered Sets
[52.134s][info][gc,marking  ] GC(8) Concurrent Rebuild Remembered Sets 0.912ms
[52.134s][info][gc,start    ] GC(8) Pause Cleanup
[52.134s][info][gc          ] GC(8) Pause Cleanup 165M->165M(512M) 0.222ms
[52.134s][info][gc,cpu      ] GC(8) User=0.00s Sys=0.00s Real=0.00s
[52.134s][info][gc,marking  ] GC(8) Concurrent Cleanup for Next Mark
[52.135s][info][gc,marking  ] GC(8) Concurrent Cleanup for Next Mark 1.413ms
[52.136s][info][gc          ] GC(8) Concurrent Mark Cycle 5.318ms
[58.926s][info][gc,start    ] GC(9) Pause Young (Prepare Mixed) (G1 Evacuation Pause)
[58.926s][info][gc,task     ] GC(9) Using 10 workers of 10 for evacuation
[58.934s][info][gc,phases   ] GC(9)   Pre Evacuate Collection Set: 0.4ms
[58.934s][info][gc,phases   ] GC(9)   Merge Heap Roots: 0.4ms
[58.935s][info][gc,phases   ] GC(9)   Evacuate Collection Set: 6.0ms
[58.935s][info][gc,phases   ] GC(9)   Post Evacuate Collection Set: 1.1ms
[58.935s][info][gc,phases   ] GC(9)   Other: 0.6ms
[58.935s][info][gc,heap     ] GC(9) Eden regions: 45->0(17)
[58.935s][info][gc,heap     ] GC(9) Survivor regions: 12->8(8)
[58.935s][info][gc,heap     ] GC(9) Old regions: 154->202
[58.935s][info][gc,heap     ] GC(9) Archive regions: 0->0
[58.935s][info][gc,heap     ] GC(9) Humongous regions: 0->0
[58.935s][info][gc,metaspace] GC(9) Metaspace: 785K(896K)->785K(896K) NonClass: 723K(768K)->723K(768K) Class: 62K(128K)->62K(128K)
[58.935s][info][gc          ] GC(9) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 210M->209M(512M) 9.214ms
[58.935s][info][gc,cpu      ] GC(9) User=0.05s Sys=0.08s Real=0.01s
[61.466s][info][gc,start    ] GC(10) Pause Young (Mixed) (G1 Evacuation Pause)
[61.466s][info][gc,task     ] GC(10) Using 10 workers of 10 for evacuation
[61.468s][info][gc,phases   ] GC(10)   Pre Evacuate Collection Set: 0.1ms
[61.468s][info][gc,phases   ] GC(10)   Merge Heap Roots: 0.1ms
[61.468s][info][gc,phases   ] GC(10)   Evacuate Collection Set: 0.7ms
[61.468s][info][gc,phases   ] GC(10)   Post Evacuate Collection Set: 0.2ms
[61.468s][info][gc,phases   ] GC(10)   Other: 0.2ms
[61.468s][info][gc,heap     ] GC(10) Eden regions: 17->0(90)
[61.468s][info][gc,heap     ] GC(10) Survivor regions: 8->4(4)
[61.468s][info][gc,heap     ] GC(10) Old regions: 202->198
[61.468s][info][gc,heap     ] GC(10) Archive regions: 0->0
[61.468s][info][gc,heap     ] GC(10) Humongous regions: 0->0
[61.468s][info][gc,metaspace] GC(10) Metaspace: 785K(896K)->785K(896K) NonClass: 723K(768K)->723K(768K) Class: 62K(128K)->62K(128K)
[61.468s][info][gc          ] GC(10) Pause Young (Mixed) (G1 Evacuation Pause) 226M->201M(512M) 1.443ms
[61.468s][info][gc,cpu      ] GC(10) User=0.00s Sys=0.00s Real=0.00s

 

 

GC(6)에서 Young GC가 발생한다.

[39.828s][info][gc,start    ] GC(6) Pause Young (Normal) (G1 Evacuation Pause)
[39.828s][info][gc,task     ] GC(6) Using 10 workers of 10 for evacuation
[39.834s][info][gc,phases   ] GC(6)   Pre Evacuate Collection Set: 0.1ms
[39.834s][info][gc,phases   ] GC(6)   Merge Heap Roots: 0.0ms
[39.834s][info][gc,phases   ] GC(6)   Evacuate Collection Set: 5.6ms
[39.834s][info][gc,phases   ] GC(6)   Post Evacuate Collection Set: 0.2ms
[39.835s][info][gc,phases   ] GC(6)   Other: 0.1ms
[39.835s][info][gc,heap     ] GC(6) Eden regions: 67->0(81)
[39.835s][info][gc,heap     ] GC(6) Survivor regions: 8->10(10)
[39.835s][info][gc,heap     ] GC(6) Old regions: 186->240
[39.835s][info][gc,heap     ] GC(6) Archive regions: 0->0
[39.835s][info][gc,heap     ] GC(6) Humongous regions: 0->0

Eden Regions의 67개의 region이 이동 대상으로 선정되었다. (81)은 Eden 영역의 최대 개수이다.

Survivor 영역은 10개로 되었고

Survivor로 가지못한 Eden regions의 영역들은 Old region으로 승격(promotion)되었다.

나머지 11개는 회수된 듯하다.

 

 

Concurrent Marking(동시 마킹) 사이클 시작

[52.120s][info][gc,start    ] GC(7) Pause Young (Concurrent Start) (G1 Evacuation Pause)
//...
[52.130s][info][gc          ] GC(8) Concurrent Mark Cycle
[52.130s][info][gc,marking  ] GC(8) Concurrent Clear Claimed Marks
[52.130s][info][gc,marking  ] GC(8) Concurrent Clear Claimed Marks 0.018ms
[52.130s][info][gc,marking  ] GC(8) Concurrent Scan Root Regions
[52.130s][info][gc,marking  ] GC(8) Concurrent Scan Root Regions 0.205ms
[52.130s][info][gc,marking  ] GC(8) Concurrent Mark
[52.131s][info][gc,marking  ] GC(8) Concurrent Mark From Roots
[52.131s][info][gc,task     ] GC(8) Using 3 workers of 3 for marking
[52.131s][info][gc,marking  ] GC(8) Concurrent Mark From Roots 0.893ms
[52.131s][info][gc,marking  ] GC(8) Concurrent Preclean
[52.132s][info][gc,marking  ] GC(8) Concurrent Preclean 0.077ms
[52.132s][info][gc,start    ] GC(8) Pause Remark
[52.133s][info][gc          ] GC(8) Pause Remark 330M->165M(512M) 0.949ms
[52.133s][info][gc,cpu      ] GC(8) User=0.00s Sys=0.00s Real=0.00s
[52.133s][info][gc,marking  ] GC(8) Concurrent Mark 2.183ms
[52.133s][info][gc,marking  ] GC(8) Concurrent Rebuild Remembered Sets
[52.134s][info][gc,marking  ] GC(8) Concurrent Rebuild Remembered Sets 0.912ms
[52.134s][info][gc,start    ] GC(8) Pause Cleanup
[52.134s][info][gc          ] GC(8) Pause Cleanup 165M->165M(512M) 0.222ms
[52.134s][info][gc,cpu      ] GC(8) User=0.00s Sys=0.00s Real=0.00s
[52.134s][info][gc,marking  ] GC(8) Concurrent Cleanup for Next Mark
[52.135s][info][gc,marking  ] GC(8) Concurrent Cleanup for Next Mark 1.413ms
[52.136s][info][gc          ] GC(8) Concurrent Mark Cycle 5.318ms

Pause Young (Concurrent Start) 이때 Initial Mark가 진행된 듯 하다. 따로 로그에는 안찍힌다.

 

Scan Root Regions : Survivor 영역이 참조하는 Old 객체를 스캔

Mark From Roots : 애플리케이션 실행 중에(Concurrent) 힙 전체를 돌며 살아있는 객체 찾음

Remark 330M -> 165M:  STW후 최종 생존 객체를 확정 ( Reference Processing나 Class Unloading이 일어나면서 메모리 확보 될 수 있음)

 Cleanup : STW 발생, 살아 있는 객체 비율 계산, 여기서는 변화 없음 즉, 완전히 텅 빈 리전은 없다는 의미

 

 

Mixed GC

[58.935s][info][gc          ] GC(9) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 210M->209M(512M) 9.214ms
[58.935s][info][gc,cpu      ] GC(9) User=0.05s Sys=0.08s Real=0.01s
[61.466s][info][gc,start    ] GC(10) Pause Young (Mixed) (G1 Evacuation Pause)
[61.466s][info][gc,task     ] GC(10) Using 10 workers of 10 for evacuation
[61.468s][info][gc,phases   ] GC(10)   Pre Evacuate Collection Set: 0.1ms
[61.468s][info][gc,phases   ] GC(10)   Merge Heap Roots: 0.1ms
[61.468s][info][gc,phases   ] GC(10)   Evacuate Collection Set: 0.7ms
[61.468s][info][gc,phases   ] GC(10)   Post Evacuate Collection Set: 0.2ms
[61.468s][info][gc,phases   ] GC(10)   Other: 0.2ms
[61.468s][info][gc,heap     ] GC(10) Eden regions: 17->0(90)
[61.468s][info][gc,heap     ] GC(10) Survivor regions: 8->4(4)
[61.468s][info][gc,heap     ] GC(10) Old regions: 202->198
[61.468s][info][gc,heap     ] GC(10) Archive regions: 0->0
[61.468s][info][gc,heap     ] GC(10) Humongous regions: 0->0
[61.468s][info][gc,metaspace] GC(10) Metaspace: 785K(896K)->785K(896K) NonClass: 723K(768K)->723K(768K) Class: 62K(128K)->62K(128K)
[61.468s][info][gc          ] GC(10) Pause Young (Mixed) (G1 Evacuation Pause) 226M->201M(512M) 1.443ms
[61.468s][info][gc,cpu      ] GC(10) User=0.00s Sys=0.00s Real=0.00s

 

prepare Mixed : Old 영역 중 어디를 먼저 청소할 지 (CSet 후보 선정)정하는 단계

 

Pause Young (Mixed) : Mixed GC 시작

[61.468s][info][gc,heap     ] GC(10) Eden regions: 17->0(90)
[61.468s][info][gc,heap     ] GC(10) Survivor regions: 8->4(4)
[61.468s][info][gc,heap     ] GC(10) Old regions: 202->198

실제로 young 영역과 old 영역이 줄어든 것을 확인 할 수 있음

 

 

Evacuate Collection Set: 10.6ms

CSet에서 살아남은 객체들을 새로운 Region으로 복사하는 과정

 

 

Full GC도 억지로 강제로 일으켜보면

[77.263s][info][gc             ] GC(35) Pause Full (G1 Compaction Pause) 381M->380M(512M) 11.908ms
[77.264s][info][gc,cpu         ] GC(35) User=0.02s Sys=0.00s Real=0.01s
[77.264s][info][gc,marking     ] GC(36) Concurrent Mark From Roots 12.259ms
[77.264s][info][gc,marking     ] GC(36) Concurrent Mark Abort
[77.264s][info][gc             ] GC(36) Concurrent Mark Cycle 13.283ms
[77.518s][info][gc,start       ] GC(37) Pause Young (Normal) (G1 Preventive Collection)
[77.518s][info][gc,task        ] GC(37) Using 10 workers of 10 for evacuation
[77.522s][info][gc,phases      ] GC(37)   Pre Evacuate Collection Set: 0.5ms
[77.522s][info][gc,phases      ] GC(37)   Merge Heap Roots: 0.4ms
[77.522s][info][gc,phases      ] GC(37)   Evacuate Collection Set: 1.0ms
[77.522s][info][gc,phases      ] GC(37)   Post Evacuate Collection Set: 1.2ms
[77.522s][info][gc,phases      ] GC(37)   Other: 0.6ms
[77.522s][info][gc,heap        ] GC(37) Eden regions: 2->0(23)
[77.522s][info][gc,heap        ] GC(37) Survivor regions: 0->2(2)
[77.522s][info][gc,heap        ] GC(37) Old regions: 508->508
[77.522s][info][gc,heap        ] GC(37) Archive regions: 0->0
[77.522s][info][gc,heap        ] GC(37) Humongous regions: 0->0

마킹 시간도 오래걸리고 처리도 느리다..