GC Log 로 확인하는 G1GC 동작 과정

작은 파란색 원 : Oracle 문서에서는 regular young-only collection 이라고 표현, Young 영역에 대한 GC 발생 (STW)

작은 분홍색 원 : Oracle 문서에서는 multiple mixed colletions 이라고 표현, Young 과 Old 영역 모두에 대한 GC 발생 (STW)

원의 크기는 STW 의 소요 시간과 비례한다. 

 

 

1. G1GC 는 regular young-only collection 만 주기적으로 진행
   • GC 로그 상 Eden 영역이 가득 찼을때 regular young-only collection 이 트리거되는것으로 보임
2. regular young-only collection 만 진행하다가 Old 영역의 사용량이 임계치에 도달하면 Initial Mark 단계를 시작
   • Initial Mark 단계는 regular young-only collection 을 실행하면서 함께 Marking 을 한다.
   • Old 영역에 있는 객체들 중 Space Reclamation 단계에서도 살아 남아야하는 객체들에 대한 마킹을 한다.
3. Initial Mark 단계가 끝나면 Remark 단계가 시작
   • Remark 단계에서는 Marking 을 끝내고 회수 가능으로 표시한 객체를 회수한다 ( class unloading )
   • 이때 다른 GC 작업들은 멈추게 된다.
   • Cleanup 단계에서 사용하기 위해서 참조가 살아있는 객체들에 대한 요약 정보를 계산한다.
4. Remark 단계가 끝나면 Cleanup 단계가 시작
   • Cleanup 단계에서는 Empty Region 에 대한 회수를 하게 된다. ( Remark 에서는 Region 안에 있는 객체를 회수하고 Cleanup 단계에서는 비어있는 Region 을 회수? )
   • Space Reclamation 단계가 필요할지 결정하게되어 Remark 이후에 다시 Young-only 단계가 실행될 수도 있고 Space Reclamation 단계가 실행 될 수 있다.
   • Space Reclamation 단계가 실행된다면 regular young-only collection 이 한번 실행되고 진입
5. Remark 단계에서 Space Reclamation 단계가 필요하다고 판단하여 Space Reclamation 단계가 실행
   • Young 영역 뿐만 아니라 Old 영역에 대한 회수가 진행됨
   • G1 이 노력에 비해서 회수되는 힙 영역이 적다고 판단되면 Space Reclamation 단계를 끝내고 다시 Young-only 단계로 진입

 

GC 로그로 각 GC 단계를 확인

regular young-only collection 이 주기적으로 실행되는 로그

2023-10-12T23:14:34.907+0900: 746373.175: [GC pause (G1 Humongous Allocation) (young), 0.0924983 secs]
   [Parallel Time: 81.0 ms, GC Workers: 3]
   ...
   [Eden: 2104.0M(3040.0M)->0.0B(3064.0M) Survivors: 32768.0K->8192.0K Heap: 4868.6M(5120.0M)->943.9M(5120.0M)]
 [Times: user=0.25 sys=0.01, real=0.09 secs] 
2023-10-12T23:15:34.205+0900: 746432.473: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted), 0.4256543 secs]
   [Parallel Time: 242.5 ms, GC Workers: 3]
   ...
   [Eden: 2896.0M(3064.0M)->0.0B(3056.0M) Survivors: 8192.0K->16384.0K Heap: 4997.9M(5120.0M)->1440.6M(5120.0M)]
 [Times: user=1.04 sys=0.10, real=0.43 secs]

 

regular young-only collection 이 실행되면서 initial-mark 단계에 진입한 로그

2023-10-12T23:16:34.210+0900: 746492.478: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0498040 secs]
   [Parallel Time: 43.9 ms, GC Workers: 3]
   ...
   [Eden: 2328.0M(3056.0M)->0.0B(3040.0M) Survivors: 16384.0K->32768.0K Heap: 4540.9M(5120.0M)->1451.3M(5120.0M)]
 [Times: user=0.14 sys=0.00, real=0.05 secs]

 

Marking 이 시작되고 끝나는 로그

2023-10-12T23:16:34.260+0900: 746492.528: [GC concurrent-root-region-scan-start]
2023-10-12T23:16:34.362+0900: 746492.631: [GC concurrent-root-region-scan-end, 0.1024034 secs]
2023-10-12T23:16:34.362+0900: 746492.631: [GC concurrent-mark-start]
2023-10-12T23:16:35.839+0900: 746494.108: [GC concurrent-mark-end, 1.4769077 secs]

 

Remark 단계에서 Marking 을 끝내고 Class unloading 에 대한 로그

2023-10-12T23:16:35.841+0900: 746494.109: [GC remark 2023-10-12T23:16:35.841+0900: 746494.109: [Finalize Marking, 0.0028733 secs] 2023-10-12T23:16:35.844+0900: 746494.112: [GC ref-proc, 0.0012985 secs] 2023-10-12T23:16:35.845+0900: 746494.113: [Unloading, 0.0325817 secs], 0.0384588 secs]
 [Times: user=0.11 sys=0.00, real=0.04 secs]

 

Cleanup 단계가 진행됨

2023-10-12T23:16:35.881+0900: 746494.149: [GC cleanup 2238M->1638M(5120M), 0.0036217 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2023-10-12T23:16:35.884+0900: 746494.153: [GC concurrent-cleanup-start]
2023-10-12T23:16:35.885+0900: 746494.153: [GC concurrent-cleanup-end, 0.0004371 secs]

 

Cleanup 단계에서 G1 이 Space Reclamation 단계가 필요하다고 판단 하여 regular young-only collection 한번 진행

2023-10-12T23:17:34.241+0900: 746552.509: [GC pause (G1 Humongous Allocation) (young), 0.0293678 secs]
   [Parallel Time: 25.0 ms, GC Workers: 3]
	...
   [Eden: 2504.0M(3040.0M)->0.0B(224.0M) Survivors: 32768.0K->32768.0K Heap: 4920.9M(5120.0M)->860.0M(5120.0M)]
 [Times: user=0.08 sys=0.00, real=0.03 secs]

 

Space Reclamation 단계에 진입하여 mixed GC 가 발생

2023-10-12T23:17:48.709+0900: 746566.977: [GC pause (G1 Evacuation Pause) (mixed), 0.0121526 secs]
   [Parallel Time: 9.8 ms, GC Workers: 3]
   ...
   [Eden: 224.0M(224.0M)->0.0B(3064.0M) Survivors: 32768.0K->8192.0K Heap: 1829.1M(5120.0M)->816.6M(5120.0M)]
 [Times: user=0.03 sys=0.00, real=0.01 secs]