GC Log 확인하기

GC Log 남기기

java -jar ~~~ -Xlog:gc*:file=gclog/gc.log.$(date +%Y-%m-%d):time,tags:filecount=5,filesize=10m

위와 같이 JVM을 실행시킬 때 GC 로그를 남기는 옵션을 지정해줄 수 있다.

위 명령어를 통해 어떤 로그가 남는지 확인해보자.

GC Log

[2024-03-15T08:27:48.454+0000][gc] Using Serial
[2024-03-15T08:27:48.454+0000][gc,init] Version: 17.0.10+8-LTS (release)
[2024-03-15T08:27:48.454+0000][gc,init] CPUs: 1 total, 1 available
[2024-03-15T08:27:48.454+0000][gc,init] Memory: 949M
[2024-03-15T08:27:48.454+0000][gc,init] Large Page Support: Disabled
[2024-03-15T08:27:48.454+0000][gc,init] NUMA Support: Disabled
[2024-03-15T08:27:48.454+0000][gc,init] Compressed Oops: Enabled (32-bit)
[2024-03-15T08:27:48.454+0000][gc,init] Heap Min Capacity: 8M
[2024-03-15T08:27:48.454+0000][gc,init] Heap Initial Capacity: 16M
[2024-03-15T08:27:48.454+0000][gc,init] Heap Max Capacity: 238M
[2024-03-15T08:27:48.454+0000][gc,init] Pre-touch: Disabled
[2024-03-15T08:27:48.490+0000][gc,metaspace] CDS archive(s) mapped at: [0x00007fdd04000000-0x00007fdd04bba000-0x00007fdd04bba000), size 12296192, SharedBaseAddress: 0x00007fdd04000000, ArchiveRelocationMode: 1.
[2024-03-15T08:27:48.490+0000][gc,metaspace] Compressed class space mapped at: 0x00007fdd05000000-0x00007fdd45000000, reserved size: 1073741824
[2024-03-15T08:27:48.490+0000][gc,metaspace] Narrow klass base: 0x00007fdd04000000, Narrow klass shift: 0, Narrow klass range: 0x100000000
[2024-03-15T08:27:48.702+0000][gc,start    ] GC(0) Pause Young (Allocation Failure)
[2024-03-15T08:27:48.704+0000][gc,heap     ] GC(0) DefNew: 3882K(4928K)->512K(4928K) Eden: 3882K(4416K)->0K(4416K) From: 0K(512K)->512K(512K)
[2024-03-15T08:27:48.704+0000][gc,heap     ] GC(0) Tenured: 0K(10944K)->568K(10944K)
[2024-03-15T08:27:48.704+0000][gc,metaspace] GC(0) Metaspace: 868K(960K)->868K(960K) NonClass: 794K(832K)->794K(832K) Class: 73K(128K)->73K(128K)
[2024-03-15T08:27:48.704+0000][gc          ] GC(0) Pause Young (Allocation Failure) 3M->1M(15M) 2.428ms
[2024-03-15T08:27:48.704+0000][gc,cpu      ] GC(0) User=0.00s Sys=0.00s Real=0.00s
[2024-03-15T08:27:48.765+0000][gc,start    ] GC(1) Pause Young (Allocation Failure)
[2024-03-15T08:27:48.767+0000][gc,heap     ] GC(1) DefNew: 4896K(4928K)->260K(4928K) Eden: 4384K(4416K)->0K(4416K) From: 512K(512K)->260K(512K)
[2024-03-15T08:27:48.767+0000][gc,heap     ] GC(1) Tenured: 568K(10944K)->1079K(10944K)
[2024-03-15T08:27:48.767+0000][gc,metaspace] GC(1) Metaspace: 892K(1024K)->892K(1024K) NonClass: 818K(896K)->818K(896K) Class: 73K(128K)->73K(128K)
[2024-03-15T08:27:48.767+0000][gc          ] GC(1) Pause Young (Allocation Failure) 5M->1M(15M) 1.714ms
[2024-03-15T08:27:48.767+0000][gc,cpu      ] GC(1) User=0.01s Sys=0.01s Real=0.00s
[2024-03-15T08:27:49.001+0000][gc,start    ] GC(2) Pause Young (Allocation Failure)
[2024-03-15T08:27:49.002+0000][gc,heap     ] GC(2) DefNew: 4676K(4928K)->511K(4928K) Eden: 4416K(4416K)->0K(4416K) From: 260K(512K)->511K(512K)
[2024-03-15T08:27:49.002+0000][gc,heap     ] GC(2) Tenured: 1079K(10944K)->1370K(10944K)
[2024-03-15T08:27:49.002+0000][gc,metaspace] GC(2) Metaspace: 1256K(1472K)->1256K(1472K) NonClass: 1161K(1280K)->1161K(1280K) Class: 94K(192K)->94K(192K)
[2024-03-15T08:27:49.002+0000][gc          ] GC(2) Pause Young (Allocation Failure) 5M->1M(15M) 1.559ms
[2024-03-15T08:27:49.002+0000][gc,cpu      ] GC(2) User=0.00s Sys=0.00s Real=0.01s
[2024-03-15T08:27:49.121+0000][gc,start    ] GC(3) Pause Young (Allocation Failure)
[2024-03-15T08:27:49.123+0000][gc,heap     ] GC(3) DefNew: 4927K(4928K)->72K(4928K) Eden: 4416K(4416K)->0K(4416K) From: 511K(512K)->72K(512K)
[2024-03-15T08:27:49.123+0000][gc,heap     ] GC(3) Tenured: 1370K(10944K)->1867K(10944K)
[2024-03-15T08:27:49.123+0000][gc,metaspace] GC(3) Metaspace: 1643K(1792K)->1643K(1792K) NonClass: 1519K(1600K)->1519K(1600K) Class: 124K(192K)->124K(192K)
[2024-03-15T08:27:49.123+0000][gc          ] GC(3) Pause Young (Allocation Failure) 6M->1M(15M) 1.480ms
[2024-03-15T08:27:49.123+0000][gc,cpu      ] GC(3) User=0.00s Sys=0.00s Real=0.01s
[2024-03-15T08:27:49.212+0000][gc,start    ] GC(4) Pause Young (Allocation Failure)
[2024-03-15T08:27:49.213+0000][gc,heap     ] GC(4) DefNew: 4488K(4928K)->145K(4928K) Eden: 4416K(4416K)->0K(4416K) From: 72K(512K)->145K(512K)
[2024-03-15T08:27:49.213+0000][gc,heap     ] GC(4) Tenured: 1867K(10944K)->1867K(10944K)
[2024-03-15T08:27:49.213+0000][gc,metaspace] GC(4) Metaspace: 1956K(2112K)->1956K(2112K) NonClass: 1798K(1920K)->1798K(1920K) Class: 158K(192K)->158K(192K)
[2024-03-15T08:27:49.213+0000][gc          ] GC(4) Pause Young (Allocation Failure) 6M->1M(15M) 0.710ms
[2024-03-15T08:27:49.213+0000][gc,cpu      ] GC(4) User=0.00s Sys=0.00s Real=0.00s
[2024-03-15T08:27:49.345+0000][gc,start    ] GC(5) Pause Young (Allocation Failure)
[2024-03-15T08:27:49.346+0000][gc,heap     ] GC(5) DefNew: 4561K(4928K)->269K(4928K) Eden: 4416K(4416K)->0K(4416K) From: 145K(512K)->269K(512K)
[2024-03-15T08:27:49.346+0000][gc,heap     ] GC(5) Tenured: 1867K(10944K)->1867K(10944K)
[2024-03-15T08:27:49.346+0000][gc,metaspace] GC(5) Metaspace: 2597K(2816K)->2597K(2816K) NonClass: 2364K(2496K)->2364K(2496K) Class: 232K(320K)->232K(320K)
[2024-03-15T08:27:49.346+0000][gc          ] GC(5) Pause Young (Allocation Failure) 6M->2M(15M) 1.023ms
[2024-03-15T08:27:49.346+0000][gc,cpu      ] GC(5) User=0.00s Sys=0.00s Real=0.00s

약 5회를 수행한 GC로그를 긁어왔다. 위와 같은 형태로 로깅을 지속한다.

위 로그를 아래와 같이 컬럼으로 구분하겠다.

[발생 시각] [GC 요약] [GC 싸이클] [GC 세부 내용]

예를들어, [2024-03-15T08:27:49.346+0000][gc,cpu ] GC(5) User=0.00s Sys=0.00s Real=0.00s라는 로그는

• 2024-03-15T08:27:49.346+0000에 실행되었고
• gc cpu에 관한 작업을 로그를 나타내며
• 5번째 GC에서 발생한 로그이고
• 사용자, 시스템, 실제 시간이 얼마나 걸렸는지를 나타낸다. Real 시간은 GC로 인한 STW를 가리킨다.

---

로그 조금 더 세부적으로 봐보기

GC Init

• [2024-03-15T08:27:48.454+0000][gc] Using Serial는 GC 사용 방식을 나타낸다.

• [2024-03-15T08:27:48.454+0000][gc,init] Version: 17.0.10+8-LTS (release)는 JVM 버전 및 설정을 의미한다. 현재 나의 JVM은 Java 17 LTS 버전을 사용 중이다.

• CPUs: 1 total, 1 available는 사용 가능한 CPU 코어가 1개임을 나타낸다.

• Memory: 949M는 JVM에 할당된 메모리는 총 949MB임을 나타낸다.

• Large Page Support: Disabled는 Large Page 지원이 비활성화되어 있음을 나타낸다. Large Page를 사용하면 메모리 관리가 효율적으로 이루어질 수 있으나, 모든 시스템에서 지원되는 것은 아니다.

• NUMA(Non-Uniform Memory Access) 지원을 비활성화한다. NUMA는 멀티프로세서 시스템에서 메모리 접근 시간을 최적화하는 방식이다.

• Compressed Oops: Enabled (32-bit)는 Compressed Oops(Object-Oriented Pointers)가 활성화되어 있으며, 32비트 모드로 동작함을 나타낸다. Oops는 자바 객체에 대한 포인터를 의미하고 포인터 압축을 통해 메모리 사용량을 줄일 수 있다.

• Heap Min Capacity: 8M, Heap Initial Capacity: 16M, Heap Max Capacity: 238M는 힙 메모리의 최소 용량은 8MB, 초기 용량은 16MB, 최대 용량은 238MB임을 나타낸다.

• [2024-03-15T08:27:48.454+0000][gc,init] Pre-touch: Disabled는 프리터치(pre-touch) 기능이 비활성화되어 있음을 나타낸다. 프리터치를 사용하면 JVM이 힙 메모리를 실제로 접근하여 페이지를 메모리에 로드하여 GC동작 시 지연을 줄일 수 있다.

• CDS archive(s) mapped at: [0x00007fdd04000000-0x00007fdd04bba000-0x00007fdd04bba000)는 클래스 데이터 공유(CDS) 아카이브가 메모리 주소 0x00007fdd04000000부터 0x00007fdd04bba000까지 매핑되어 있음을 나타낸다. CDS는 자주 사용되는 클래스를 메모리에 미리 로드하여 JVM의 시작 시간과 메모리 사용량을 줄이는 기능이다. (JIT 컴파일러에 의해 지정되는 클래스들이다.)

• Compressed class space mapped at: 0x00007fdd05000000-0x00007fdd45000000, reserved size: 1073741824는 압축된 클래스 공간이 메모리 주소 0x00007fdd05000000부터 0x00007fdd45000000까지 매핑되어 있음을 나타낸다. 예약된 크기는 1073741824바이트(1GB)임을 나타낸다. 이 공간은 압축된 Oops를 사용하는 클래스 메타데이터를 저장하는 데 사용된다.

GC Event

그 이후의 로그들은 가비지 컬렉션 이벤트이다. 특히, Yong Generation에 대한 로그를 남기는데, 자세한 설명은 아래와 같다.

첫 번째 GC 이벤트 (GC(0))

• 시작 시간
  • 2024-03-15T08:27:48.702+0000
• 이벤트 유형
  • Pause Young (Allocation Failure) - Young Generation에서의 메모리 할당 실패로 인해 발생한 GC 이벤트이다. 즉, Young Generation에 더 이상 객체를 할당할 공간이 없어 GC가 실행되었다.
• 메모리 상태 변화
  • DefNew: 3882K에서 512K로 감소, 이는 Young Generation의 Eden 영역과 Survivors 영역 중 하나인 From 영역의 메모리 사용량이다.
  • Eden: 3882K에서 0K로 감소, Eden 영역의 모든 객체가 GC 과정에서 정리되었음을 의미한다.
  • From: 0K에서 512K로 증가, Survivors 영역 중 하나인 From 영역에 객체들이 이동했다.
  • Tenured: 0K에서 568K로 증가, 일부 객체가 Old Generation으로 이동했다.
• 소요 시간: 2.428ms