안녕하세요. 일반적인 GC 내용과 G1GC (Garbage-First Garbage Collector) 내용 포스트입니다.
오라클의 G1GC (Garbage-Fist Garbage Collector) 내용과 제가 경험했던 내용들을 정리하여 포스팅을 하려고 합니다.
JDK 8 (Hotspot) 버전에 초점을 맞춰으로 소개드리니 참고바라며, Java 8에서 부족한 내용에 대해서는 다른 버전의 내용에서도 참고하였습니다. 각 버전마다 조금씩 상이하긴하지만 크게 차이는 없으니 다른 버전을 사용하셔도 개념을 이해하시는 목적으로는 무관합니다.

GC와 관련된 내용은 유튜브에서 영상으로 다루고 있습니다. Link

JVM 메모리 구조와 Garbage Collector

우선 G1GC를 알기 전에 JVM 메모리 구조에 대해서 알아야 합니다.
위 이미지는 JVM 메모리 구조 포스트에서 다뤘던 자료인데, 다시 재활용하게 되네요.
GC(Garbage Collector)는 Heap 메모리에서 활동하며, JVM에서 GC의 스케줄링을 담당하여 개발자가 직접 관여하지 않아도 더이상 사용하지 않는 점유된 메모리를 제거해주는 역할을 담당합니다.

GC의 원리

GC가 가능했던건 ‘weak generational hypothesis’라는 가설 덕분이었습니다.

대부분의 객체는 금방 접근 불가능(unreachable)한 상태가 된다.

대부분의 객체는 중괄호({}) 안에서 생성됩니다.
이 객체들은 괄호가 끝나는 시점에 더이상 사용되지 않습니다.
특수한 경우에는 오래 사용될 수 있지만, 대부분의 경우는 unreachable한 상태가 되어 GC의 대상이 됩니다.

오래된 객체에서 젊은 객체로의 참조는 아주 적게 발생한다.

일반적으로 순차적인 로직에 의해 객체를 생성하여 활용하게 됩니다.
이 과정에서 앞에서 생성된 객체는 그 다음의 로직에서 사용된 이후 대부분 사용되지 않게 됩니다.
그러한 특성으로 인해 더이상 참조되지 않는 객체에 대해 GC를 할 수 있게 됩니다.

※ 위 설명에 대해서는 부연적인 설명을 위한 코드를 추가하도록 하겠습니다.

일반적인 GC 과정

GC는 간단하게 말해서 Heap Area에서 더이상 사용하지 않는 메모리를 제거하는 것을 말합니다.
전통적인 Heap Area는 위 이미지에서 보실 수 있듯이, Eden, Survivor1, Survivor2, Old Generation으로 구분이 됩니다. Eden, Survivor1, 2를 합쳐서 Young Generation이라고 묶어서 부르기도 합니다.
각 영역은 저마다의 역할이 있으며, GC는 각 영역을 활용하여 최적의 메모리 운영을 하게 됩니다.

1. 맨 처음 객체가 생성이 되면 Eden 영역에 생성이 됩니다.
2. 그리고 GC의 일종인 Minor GC가 발생하면 미사용 객체의 제거와 함께 아직 사용되는 것으로 판단되는 객체들을 Survivor1 또는 Survivor2 영역으로 이동시킵니다.
   단, 여기서 Survivor 영역을 거치지 않고 바로 Old Genration으로 이동하는 경우가 있는데, 객체의 크기가 Survivor 영역의 크기보다 클 경우입니다.
3. 여기서 Survivor1과 Survivor2 영역은 둘 중 한 곳에만 객체가 존재하며, 다른 한 곳은 비어져 있어야 합니다.
   보통 From, to 로 구분을 하는데, 객체가 존재하는 Survivor영역(From)이 가득 차면 다른 Survivor영역(To)으로 보내게되고, 기존의 Survivor영역(From)을 비우는 작업을 진행합니다.
4. 위 과정(1~3)을 반복하면서 Survivor 영역에서 계속 살아남는 객체들에게 일정 score가 누적이 되는데, 기준치 이상이 되면 Old Generation 영역으로 이동하게 됩니다.
5. Old Generation 영역에서 살아남았던 객체들이 일정 수준 쌓이게 되면 미사용된다고 식별된 객체들을 제거해주는 Full GC가 발생하게 됩니다.
   이 과정에서 STW(Stop-The-World)가 발생하게 됩니다.

STW란, Old Generation의 쌓인 많은 객체들을 효율적으로 제거해주기 위해 JVM이 잠시 멈추는 현상을 뜻합니다.
이 현상이 발생하게 되면 뜻하지 않은 문제들이 발생할 수 있는데, 보통 이 포스트를 보시는 분들은 이 ‘문제’를 직면하신 분들일 것이라 확신(?)합니다.

위에 설명한 과정은 일반적으로 설명되는 GC라는 개념에서 통하는 내용들입니다.
GC는 사실 종류가 다양하여 각 GC마다 동작방식이 상이하기 때문에 본인이 개발하고 있는 어플리케이션의 특성을 잘 파악하여 그에 어울리는 GC를 선정하는 것이 중요합니다.
하지만 default로 설정된 GC가 가장 효율적인 경우가 많으며, GC를 튜닝하는 것은 최종적인 수단으로 두고 Code Level에서 해결하는 것을 많은 전문가 분들이 권고하고 있습니다.
JAVA 8 이전까지는 Parallel GC가 Default로 설정되어 사용되어 왔으며, G1GC가 JAVA 6부터 소개되었고 JAVA 9부터는 Default GC로 설정되어 있습니다.

GC의 종류

이 포스트에서는 간략한 GC에 대한 설명과 G1GC에 대한 내용을 다룰 예정이기 때문에, GC의 종류는 간단하게 적고 넘어가도록 하겠습니다.

• Serial GC
  하나의 CPU로 Young 영역과 Old 영역을 연속적으로 처리하는 방식입니다.
  GC가 수행될 때 STW가 발생합니다.
  
• Parallel GC
  Parallel GC의 목표는 다른 CPU가 GC의 진행시간 동안 대기 상태로 남아 있는 것을 최소화 하는 것입니다.
  Serial GC의 Young 영역에서 진행하는 방식을 병렬로 처리하여 부하를 줄입니다.
  
• Parallel Compacting GC
  Parallel GC에서 Old 영역의 알고리즘을 변경하였습니다.
  
• Concurrent Mark-Sweep(CMS) GC
  Application의 Thread와 GC Thread가 동시에 실행되어 STW를 최소화 하는 GC입니다.
  Parallel GC와 가장 큰 차이점은 Compaction 작업 유무로 구분될 수 있습니다.
  Compaction은 메모리 공간에서 사용하지 않는 빈 공간이 없도록 옮겨서 메모리 분산을 제거하는 작업을 의미합니다.)
  
• G1(Garbage First) GC

G1GC

GC에 대한 일반적인 내용을 훑고 드디어 G1GC에 대한 본격적인 내용을 다뤄볼 차례입니다.

위 이미지는 직전에 보여드렸던 전통적인 Heap Area와 전혀 다른 모습을 보여주고 있지만, 동일한 Heap Area입니다.
G1GC는 Heap Area를 Young, Old 영역을 명확하게 구분하던 전통적인 GC들과 다르게 물리적으로 구분하지 않습니다.
개념적으로는 확실히 존재하지만, Heap Area를 일정 크기의 region으로 구분하여 논리적으로 구분하고 있습니다.

즉, HotSpot VM(Virtual Machine)의 개념은 그대로 가져와 사용합니다.
이전에 사용하던 GC들과 마찬가지로 특수한 경우(크기가 너무 큰 경우)를 제외하고는 최초 객체가 생성이 되면 Eden에 할당하고, 이후 Survivor로의 이동과 소멸, 그리고 Old Region으로의 이동의 생명주기를 가져갑니다.

G1GC는 Thread 중지 목표 시간을 기반으로 Young Generation의 크기를 설정합니다.

G1GC에 대한 간단한 소개

G1GC (Garbage First Garbage Collector)는 대용량의 메모리가 있는 멀티 프로세서 시스템을 위해 제작되었습니다.
빠른 처리 속도를 달성하면서 일시 중지 시간(STW : Stop The World)의 최소화를 충족시키기는 것이 G1GC의 목표입니다.
오라클에서는 여러 기술들을 도입하여 이 목표를 수행할 수 있게 설계하였다고 소개하고 있습니다.

Heap은 동일한 크기(메모리 크기에 따라 상이)의 영역으로 나뉘어 집합으로 분할되어 연속된 가상 메모리로 존재하게 됩니다.
일시 중지 시간을 최소화 하는 것이 목표라는 것에서 유추할 수 있듯이 G1GC도 STW를 완전히 없애지는 못합니다.

G1GC 작동 방식

G1GC는 관점을 어떻게 두냐에 따라 몇단계로 나누는지 상이할 수 있습니다.
몇가지 나눠볼 수 있는 후보군을 소개해드리고 편하게 이야기 할 수 있는 방법으로 내용을 풀어보도록 하겠습니다.

Oracle 에서 소개하는 G1GC Cycle

이 Cycle은 G1GC가 취하는 동작들을 일련의 Cycle안에 포함시켜 크게 2개의 Phase로 구분하여 소개하고 있습니다.

• Young-Only Phase : 이 단계는 Young Generation의 GC로 시작됩니다.
  Concurrent Start
  이 단계에서 Young GC를 수행하면서 동시에 Marking Phase가 진행됩니다.
  Concurrent Mark는 Old Region을 GC하기 위해 현재 도달할 수 있는 live 객체(Object)를 결정합니다.
  Concurrent Mark가 진행되는 도중에, Young GC가 동작할 수 있으며 이로 인해 방해받을 수 있습니다.
  Marking은 Remark 와 Cleanup 단계에서 STW를 발생시킬 수 있습니다.
  
  Remark
  이 일시중지는 Marking을 마무리하고 Reference 처리 및 Class Unloading을 수행하여 Empty Region을 회수하고 내부 데이터 구조를 정리합니다.
  Remark와 Cleanup 사이에서 G1은 Old Region에서 여유 공간을 회수 할 수 있도록 정보를 계산합니다.
  이 계산은 Cleanup 단계에서의 STW에서 마무리 됩니다.
  
  Cleanup
  이 단계는 Region 회수가 실제로 진행될지 결정합니다.
  만약 공간 재확보(Space-Reclamation) 단계가 온다면, young-only 단계는 1회의 Mixed-GC만 진행하고 완료됩니다.
  
• Space Reclamation
  이 단계는 Young Generation Region 말고 Old Region의 Live 객체도 비우는 여러번의 Mixed-GC로 구성되어 있습니다.
  공간 재 확보 단계는 G1이 더이상 Old Region을 효율적으로 줄일 수 없겠다고 판단되면 종료됩니다.

위 두개의 Phase가 반복되는 방식으로 진행이 되는데, 백업 역할로 liveness information을 수집하는 동안 어플리케이션이 OOM(Out of Memory)로 가게되면 다른 GC들과 마찬가지로 Full GC가 발생합니다.

GC Log 살펴보기

아래 내용을 살펴보기 위해 알아두면 좋을 용어를 아래와 같이 정리해두었습니다.

• Remember Set (RS) : 객체가 어떤 영역에 저장되어 있는지를 기록한 내용입니다.
• Collection Set (CS) : GC가 수행될 영역이 기록되어 있는 내용입니다.

Young GC는 아래와 같이 발생합니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 421.814: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1361 regions, survivors: 8 regions, predicted young region time: 5.90 ms]
 421.814: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1361 regions, survivors: 8 regions, old: 0 regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 , 0.0561392 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2714.0M(2714.0M)->0.0B(290.0M) Survivors:16.0M->16.0M Heap: 3183.0M(6144.0M)->475.0M(6144.0M)]
 [Times: user=0.37 sys=0.03, real=0.06 secs]

일반적인 GC의 형태이며 로그에서 주로 봐야 할 부분들의 설명은 아래와 같습니다.
주요 로그 내용들의 시간이 min, avg, max, diff 등으로 구분되어 있는 이유는, 여러 GC Worker Thread가 포함되어 있어 각 Thread의 작업 시간들을 통계적으로 표현한 것입니다.
개인적으로 중요하게 보는 것은 diff 부분이고, 각 작업이 비슷하게 진행되고 끝마쳐지지 않는다면, 그만큼 해당 작업에서 불균형된 객체가 포함되어 있다는 의미입니다. 튜닝을 진행하셔야 한다면 이런 부분들을 체크 해보시는게 좋습니다.

• Parallel Time : 이 작업에서 병렬처리 되는 부분에 대한 내용이 적혀있습니다.
  • Ext Root Scanning (External Root Scanning) : 병렬로 GC Worker Thread가 C Set(Collection Set)을 의미하는 Register나 Thread Stack 등의 External Root를 스캐닝하는 시간을 의미입니다.
  • Update RS (Remembered Set) : RS는 레퍼런스의 영역을 알려주면서 gc의 업무 처리를 더 빠르게 할 수 있도록 도와주는 영역입니다. 여기서는 이 영역을 GC Worker Thread가 RS를 업데이트하는데 걸리는 시간입니다.
  • Processed Buffers : GC Worker Thread가 얼만큼 버퍼 처리되었는지 표기해주는 것입니다.
  • Scan RS : RS를 스캔하는데 걸린 시간을 알려주는 영역입니다.
  • Object Copy : Young GC가 발생하고 살아있는 객체를 다른 영역 (eden, survivor, old)으로 이동시키는데 걸린 시간을 표기하고 있습니다.
  • Termination : 각 GC Worker Thread는 자신의 작업을 마치면, 다른 작업이 있는지 확인하고 종료되는데, 여기에 표기되는 시간은 Worker Thread가 종료되기 위해 사용되는 작업들까지 마친 후의 시간을 의미합니다.
• 그 외 작업들은 아래와 같습니다.
  • Clear CT : CT는 Card Table을 의미하며, RS의 메타데이터를 스캐닝하는데 사용된 CT를 비우는데 걸리는 시간을 의미합니다.
  • Choose CSet : CSet에 포함되어 있는 영역을 비우거나 수집하는 작업을 포함한 마무리 작업을 하는데 걸리는 시간을 의미합니다.
  • Ref Proc (Reference Processing) : GC 작업에서 제외되어 있던 레퍼런스 (Soft, Weak, Final 등)를 처리하는데 걸린 시간을 의미합니다.
  • Ref Enq (Reference En-Queue) : 레퍼런스를 Pending List에 등록하는데 걸리는 시간을 의미합니다.
  • Free CSet : 수집된 영역의 메모리를 비우는데 걸리는 시간을 의미합니다. 여기에는 CS 뿐만 아니라 RS를 비우는 시간도 포함됩니다.

Heap Size가 가득차 오버헤드가 발생하는 경우 아래와 같은 Young GC가 발생합니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 421.814: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1361 regions, survivors: 8 regions, predicted young region time: 5.90 ms]
 421.814: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1361 regions, survivors: 8 regions, old: 0 regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 421.814: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 2.35 %, threshold: 2.00 %, uncommitted: 0 bytes, calculated expansion a mount: 0 bytes (20.00 %)]
 , 0.0173175 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2714.0M(2714.0M)->0.0B(290.0M) Survivors:16.0M->16.0M Heap: 3183.0M(6144.0M)->475.0M(6144.0M)]
 [Times: user=0.11 sys=0.04, real=0.02 secs]

Young GC 만으로 GC 작업이 부족하다고 판단되면, Young GC 단계에서 Concurrent Cycle을 요청하게 됩니다.
그 상황에서 발생하는 로그는 아래와 같습니다.
별도 설명을 드리기 보다는 Bold 처리하여 특징 해두겠습니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 421.814: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1361 regions, survivors: 8 regions, predicted young region time: 5.90 ms]
 421.814: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1361 regions, survivors: 8 regions, old: 0 regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 421.814: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 2908749824 bytes, allocation request: 0 bytes, threshold: 2899102905 bytes (45.00 %), source: end of GC]
 , 0.0240642 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2714.0M(2714.0M)->0.0B(290.0M) Survivors:16.0M->16.0M Heap: 3183.0M(6144.0M)->475.0M(6144.0M)]
 [Times: user=0.15 sys=0.04, real=0.04 secs]

Concurrent Cycle은 아래와 같은 로그가 발생합니다. Concurrent Cycle은 Mark 작업을 하기 때문에 marking cycle이라고도 부릅니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) (initial-mark) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 429.802: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1361 regions, survivors: 8 regions, predicted young region time: 5.90 ms]
 429.802: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1361 regions, survivors: 8regions, old: 0regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 , 0.0240642 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2722.0M(2722.0M)->0.0B(2714.0M) Survivors:16.0M->16.0M Heap: 5498.8M(6144.0M)->2785.0M(6144.0M)]
 [Times: user=0.14 sys=0.00, real=0.03 secs]
2020-09-15T07:12:18.873+0000: 429.826: [GC Concurrent-root-region-scan-start]
2020-09-15T07:12:18.877+0000: 429.830: [GC Concurrent-root-region-scan-end, 0.0038716 secs]
2020-09-15T07:12:18.877+0000: 429.830: [GC Concurrent-mark-start]
2020-09-15T07:12:18.979+0000: 429.931: [GC Concurrent-mark-end, 0.1016369 secs]
2020-09-15T07:12:18.980+0000: 429.932: [GC remark
2020-09-15T07:12:18.980+0000: 429.932: [Finalize Marking, .0003376 secs] 2020-09-15T07:12:18.980+0000: 429.933: [GC ref-proc, 0.0021446 secs]
2020-09-15T07:12:18.980+0000: 429.932: [GC remark 2020-09-15T07:12:18.980+0000: 429.932: [GC Finalize Marking, 0.0003376 secs] 2020-09-15T07:12:18.980+0000: 429.933: [GC ref-proc, 0.0021446 secs]
2020-09-15T07:12:18.982+0000: 429.935: [Unloading, 0.0111485 secs], 0.0144875 secs]
 [Times: user=0.08 sys=0.01, real=0.02 secs]
2020-09-15T07:12:18.995+0000: 429.948: [GC cleanup 2840M->524M(6144M), 0.0030983 secs]
 [Times: user=0.02 sys=0.00, real=0.00 secs]
2020-09-15T07:12:18.998+0000: 429.951: [GC concurrent-cleanup-start]
2020-09-15T07:12:19.004+0000: 429.957: [GC concurrent-cleanup-end, 0.0059294 secs]

Concurrent Cycle에서는 marking을 시작합니다. 위 로그에서 주로 봐야 하는 사항들에 대한 설명은 아래와 같습니다.

• initial-mark : 이 단계에서는 root를 mark 합니다.
• Concurrent-root-region-scan : start~end 단계에서 initial-mark의 survivor 영역을 스캔하여 old 영역의 레퍼런스를 찾아 mark합니다. concurrent가 붙어있는 단계에서는 STW가 발생하지 않습니다. 하지만 이 작업은 다음 Young GC가 발생하기 전에 끝마쳐야 하며, 그렇지 않으면 다음 GC 작업에 영향을 미치게 됩니다. 다르게 생각한다면 이 과정을 진행하는 도중에 Young GC가 발생할 수 있다는 것입니다.
• Concurrent-mark : start~end 단계에서 Heap 영역에 있는 모든 객체를 찾게 됩니다.
• remark : 이 단계는 mark를 마무리하는 단계입니다. STW가 발생합니다. 사용된 SATB 버퍼를 비우게 되고, Reference Processing이 동작합니다.
• cleanup : 살아있는 객체와 Free Region에 대해 계산을 수행합니다. 그리고 RS를 정리하는 작업을 진행합니다. 이 단계에서 STW가 발생합니다. 이후 concurrent 단계에서는 STW가 발생하지 않고 Empty Region을 재정리하여 이 영역을 Free List에 추가합니다. 그리고 이 단계 이후에 Young GC를 실시할지, Old GC를 실시할지 결과를 기준으로 결정하게 됩니다.

※ G1GC는 STAB(Snapshot At The Beginning) 알고리즘을 사용하여 mark 작업을 하는데, SATB는 일시 정지가 일어난 시점 직후의 객체에 대해서만 mark 작업을 합니다. 그렇기 때문에 mark 도중 죽은 객체도 라이브 객체로 간주하게 됩니다.

Mixed GC는 아래와 같은 로그가 발생합니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 429.802: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1361 regions, survivors: 8 regions, predicted young region time: 5.90 ms]
 429.802: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1361 regions, survivors: 8 regions, old: 0 regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 , 0.0240642 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2714.0M(2714.0M)->0.0B(290.0M) Survivors:16.0M->16.0M Heap: 3183.0M(6144.0M)->475.0M(6144.0M)]
 [Times: user=0.07 sys=0.00, real=0.02 secs]

Mixed GC를 반복작업 하면서 더이상 Mixed GC가 발생할 필요가 없다고 판단되면 아래와 같은 로그가 등장합니다.

2020-09-15T07:12:18.849+0000: 429.802: [GC pause (young) 429.802: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 41899, predicted base time: 17.92 ms, remaining time: 182.08 ms, target pause time: 200.00 ms]
 429.802: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 145 regions, survivors: 8 regions, predicted young region time: 2.93 ms]
 429.802: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: reclaimable percentage not over threshold, old: 28 regions, max: 308 regions, reclaimable: 321448880 bytes (4.99%), threshold: 5.00%]
 429.802: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 145 regions, survivors: 8 regions, old: 28 regions, predicted pause time: 23.82 ms, target pause time: 200.00 ms]
 429.802: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason: reclaimable percentage not over threshold, candidate old regions: 183 regions, reclaimable: 321448880 bytes (4.99 %), threshold: 5.00 %]
 , 0.0084533 secs]
   [Parallel Time: 16.9 ms, GC Workers: 8]
     [GC Worker start (ms): Min: 429802.4, Avg: 429802.5, Max: 429802.5, Diff: 0.1]
	 [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.0, Diff: 0.3, Sum: 14.9]
	 [Update RS(ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.1, Sum: 66.5]
	   [Processed Buffers: Min: 15, Avg: 31.5, Max: 57, Diff: 42, Sum: 252]
	 [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.3]
	 [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
	 [Object Copy (ms): Min: 5.6, Avg: 5.8, Max: 6.0, Diff: 0.4, Sum: 46.3]
	 [Termination (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 1.6]
	   [Termination Attempts: Min: 449, Avg: 496.2, Max: 521, Diff: 72, Sum: 3970]
	 [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
	 [GC Worker Total (ms): Min: 16.6, Avg: 16.7, Max: 16.7, Diff: 0.1, Sum: 133.2]
	 [GC Worker End (ms): Min: 429819.1, Avg: 429819.1, Max: 429819.2, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 6.7 ms]
     [Choose CSet: 0.0 ms]
     [Ref Proc: 4.1 ms]
     [Ref Enq: 0.2 ms]
     [Redirty Cards: 0.1 ms]
     [Humongous Register: 0.1 ms]
     [Humongous Reclaim: 0.0 ms]
     [Free CSet: 1.3 ms]
   [Eden: 2714.0M(2714.0M)->0.0B(290.0M) Survivors:16.0M->16.0M Heap: 3183.0M(6144.0M)->475.0M(6144.0M)]
 [Times: user=0.02 sys=0.01, real=0.00 secs]

Full GC는 아래와 같은 로그가 발생합니다.

2020-07-23T10:45:17.925+0000: 20.620: [Full GC 2035M->875M(2048M), 1.1132194 secs]
 [Eden: 0.0B(102.0M)->0.0B(584.0M) Survivors: 0.0B->0.0B Heap: 2035.8M(2048.0M)->875.0M(2048.0M)],
[Metaspace: 77391K->77391K(1120256K)]
 [Times: user=1.56 sys=0.00, real=1.11 secs]

위 로그를 보면 Full GC 라고 명시적으로 표기가 되어 있고, 각 메모리 영역이 어떻게 처리가 되었는지 표기됩니다.

(아직 내용을 보충하고 있습니다. 이 내용이 급하게 필요하신 분이 있으시면 댓글로 요청주세요!)

Updated by 20.11.07 일반적인 GC 내용과 G1GC (Garbage-First Garbage Collector) 내용
Site : @ThinkGround
Instagram : @thinkground_official
Facebook : @ThinkGround
Twitter : @ThinkG_Flature