[JAVA] Garbage Collector

728x90

Java는 프로그램에서 메모리를 명시적으로 지정하여 해제하지 않는다. 가끔 명시적으로 해제하려고 해당 객체를 null로 지정하거나 System.gc() 메서드를 호출하는 개발자가 있다. null로 지정하는 것은 큰 문제가 안 되자만, System.gc() 메서드를 호출하는 것은 시스템의 성능에 매우 큰 영향을 끼치므로 System.gc() 메서드는 절대로 사용하면 안된다.

Java에서는 개발자가 프로그램 코드로 메모리를 명시적으로 해제하지 않기 때문에 가비지 컬렉터(Garbage Collector)가 더 이상 필요 없는(쓰레기) 객체를 찾아 지우는 작업을 한다.

Garbage Collection

Garbage Collection이란?

- 객체가 접근 불가능한 상태(Unreachable)가 되었을 때, 메모리가 누적되므로 이를 수거하는 작업 GC를 실행하는 쓰레드를 제외한 나머지 쓰레드는 모두 작업을 멈춘다 = stop the world

*대게 우리가 알고 있는 GC 튜닝이란, 이 stop the world 시간을 줄이는 것이다.

*JDK 8 기준 설명

JVM 메모리 구조와 Garbage Collector

GC(Garbage Collector)는 Heap 메모리에서 동작하고, JVM에서 GC의 스케줄링을 담당하여 개발자가 직접 관여하지 않아도 더이상 사용하지 않는 점유된 메모리를 제거해주는 역할을 담당한다.

GC의 원리

GC가 가능했던 'weak generational hypothesis'라는 가설 덕분이다.

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

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

해당 가설의 장점을 최대한 살리기 위해서 HotSpot VM에서는 크게 2개로 물리적 공간을 나누었다. 둘로 나눈 공간이 Young 영역과 Old 영역이다.

Young 영역(Young Generation 영역) : 새롭게 생성한 객체의 대부분이 여기에 위치한다. 대부분의 객체가 금방 접근 불가능 상태가 되기 때문에 매우 많은 객체가 Young 영역에 생성되었다가 사라진다. 이 영역에서 객체가 사라질 때 Minor GC가 발생한다고 말한다.
Old 영역(Old Generation 영역) : 접근 불가능 상태로 되지 않아 Young 영역에서 살아남은 객체가 여기로 복사된다. 대부분 Young 영역보다 크게 할당하며, 크기가 큰 만큼 Young 영역보다 GC는 적게 발생한다. 이 영역에서 객체가 사라질 때 Major GC(혹은 Full GC)가 발생한다고 말한다.

일반적인 GC 과정

힙 영역의 구조(Java(JVM) Heap Memory Structure, jdk 1.7 이전 Heap)

Eden: 새로 생성한 대부분의 객체가 위치하는 곳
S0, S1: Eden 영역에서 GC가 한번 발생한 후 살아남은 객체들이 존재하는 곳
Old Memory: Young Generation에 대한 GC가 반복되는 과정속에 살아남은 객체가 살아남는 곳특정 회수 이상 참조되어 Old 영역으로 가기 위한 Age를 달성하였을 때 이동하게 된다.
Perm: Class / Method 의 Meta 정보, static 변수 / 상수들이 저장되는 곳

GC는 간단하게 말해서 Heap Area에서 더이상 사용하지 않는 메모리를 제거하는 것을 말한다.

전통적으로 Heap Area는 위 이미지에서 볼 수 있는 Eden, Survivor1, Survivor2, Old Generation으로 구분된다. Eden, Survivor1, 2를 힙쳐서 Young Generation이라고 부르기도 한다.

*Permanent : Java 7 버전까지 Heap Area에 존재, 8 버전부터 Native method Stack에 편

각 영역은 저마다의 역할이 있으면, GC는 각 영역을 활용하여 최적의 메모리 운영을 하게 된다.

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

STW(Stop-The-World)란, Old Generation의 쌓인 많은 객체들을 효율적으로 제거해주기 위해(GC를 실행하기 위해) JVM이 애플리케이션 실행을 멈추는 것이다. Stop-The-World가 발생하면 GC를 실행하는 쓰레드를 제와한 나머지 쓰레드는 모두 작업을 멈춘다. GC작업을 완료한 이후에야 중단했던 작업을 다시 시작한다. 어떤 GC 알고리즘을 사용하더라도 Stop-The-World는 발생한다. 대개의 경우 GC튜닝이란 이 Stop-The-World 시간을 줄이는 것이다.

이 현상이 발생하게 되면 뜻하지 않은 문제들이 발생할 수 있는데, 보통 대부분의 문제가 여기에 해당한다.

위에 설명한 과정은 일반적으로 설명되는 GC라는 개념에서 통하는 내용들이다.

GC는 사실 종류가 다양하여 각 GC마다 동작방식이 상이하기 때문에 본인이 개발하고 있는 애플리케이션의 특성을 잘 파악하여 그에 어울리는 GC를 선정하는 것이 중요하다.

하지만 Default로 설정된 GC가 가장 효율적인 경우가 많으며, GC를 튜닝하는 것은 최종적인 수단으로 두고 Code Level에서 해결하는 것을 많은 전문가 분들이 권고하고 있다.

JAVA 8 이전까지는 Parallel GC가 Default로 설정되어 사용되어 왔으며, G1GC가 JAVA 6부터 소개되었고 JAVA 9부터는 Default GC로 설정되어있다.

현재

*Perm 영역이 Metaspace로 바뀌었다.

구분	Perm	MetaSpace
저장 정보	클래스 meta / 메소드 meta / static 변수, 싱수	클래스 meta / 메소드 meta
관리 포인트	Heap 영역 튜닝 + Perm 영역 별도	Native 영역 동적 조정
GC	Full GC	Full GC
메모리 측면	-XX: PermSize / -XX: MaxPermSize	-XX: MetaSpaceSize / -XX: MaxMetaspaceSize

가장 중요한 핵심은 Perm 영역이 Heap 이 아니라 Native 영역으로 바뀌었다는 것이다.

Native 영역의 가장 큰 특징 중의 하나는

Native 영역은 JVM에 의해서 크기가 강제되지 않고, 프로세스가 이용할 수 있는 메모리 자원을 최대로 활용할 수 있다.

만일 메모리 leak이 Classloader 을 동작하는 코드에 발생하는 것으로 의심된다면, 이는 최대 메모리를 설정하지 않았기 때문이다.

Heap 영역은 크게 2가지로 구성이 되어 있다.

Young Generation 영역 : 대부분의 객체가 GC 되는 영역, 이 영역에서 객체가 사라질 때 Minor GC가 발생

Old Generaton 영역 : Young 영역보다 크게 할당되지만, GC는 적게 발생. 이때는 Full GC 라고 일컫는다.

그렇기 때문에 Full GC는 이 stop the world 시간이 길 수 밖에 없다.

기본적으로 메모리가 크고, 처리해야 될 양이 많기 때문이다.

이 old 영역에 대한 GC를 다르게 하기 위해서 많은 알고리즘들이 존재한다.

G1GC

위 이미지는 직전에 보여드렸던 전통적인 Heap Area와 전혀 다른 모습을 보여주고 있지만, 동일한 Heap Area이다.

G1GC는 Heap Area를 Young, Old 영역을 명확하게 구분하던 전통적인 GC들과 다르게 물리적으로 구분하지 않는다.

개념적으로 확실히 존재하지만, Heap Area를 일정 크기의 region으로 구분하여 논리적으로 구분하고 있다.

Humonogous: Region 크기의 50%를 초과하는 큰 객체를 저장하기 위한 공간
Available/Unused: 아직 사용되지 않은 Region

즉, HopSpot 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-olny 단계는 1회의 Mixed-GC만 진행하고 완료된다.

Space Reclamation

이 단계는 Region 회수가 실제로 진행될지 결정한다.

공간 재 확보 단계는 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을 요청하게 된다.

그 상황에서 발생하는 로그는 아래와 같다.

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 작업을 하는데, STAB는 일시정지가 일어난 시점 직후의 객체에 대해서만 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라고 명시적으로 표기가 되어 있고, 각 메모리 영역이 어떻게 처리가 되었는지 표기된다.

728x90

저작자표시 비영리 변경금지

'👨‍🏫Study > JAVA' 카테고리의 다른 글

[JAVA] GC(Garbage Collection) 영역별 데이터 흐름 정리 (0)	2022.04.21
[JAVA] G1GC (0)	2022.04.20
[JAVA] EJB(Enterprise JavaBeans) (0)	2022.04.15
[Database] JDBC (0)	2022.04.14
[JAVA] Servlet(서블릿), JSP(Java Server Page) (0)	2022.04.14

컴공 복전생의 코딩정복기

[JAVA] Garbage Collector

Garbage Collection

'👨‍🏫Study > JAVA' 카테고리의 다른 글

댓글

티스토리툴바

[JAVA] Garbage Collector

Garbage Collection

'👨‍🏫Study > JAVA' 카테고리의 다른 글

관련글

댓글

티스토리툴바