| | | 다음의 커맨드라인 스위치를 사용해 나타나는 GC 관련 출력을 살펴보자, java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+UseParNewGC -XX:+UseConc MarkSweepGC -Xmx512m -Xms512m -XX:NewSize=24m -XX:MaxNew Size=24m -XX:SurvivorRatio=2 <app-name> |
| | 신세대 GC 311.649: [GC 311.65: [ParNew Desired survivor size 4194304 bytes, new threshold 3 (max 31) - age 1: 1848472 bytes, 1848472 total - age 2: 1796200 bytes, 3644672 total - age 3: 1795664 bytes, 5440336 total : 21647K->5312K(24576K), 0.1333032 secs] 377334K->362736K(516096K), 0.1334940 secs] |
| | 앞서의 GC 스냅샷은 신세대의 GC에 대한 설명이며, 이는 다음 정보를 제공한다.
- 이 GC를 실행할 때, 총 JVM heap은 516096K이며 신세대의 heap 크기는 24576K이다. - 이 GC가 실행될 때, 구세대의 heap 크기는 516096K-24576K=491520K이다. - 이 GC 주기의 마지막에 애플리케이션의 신세대에 배정받은 객체의 ‘나이 분포’를 설명한다. 이 GC 주기는 new threshold=3으로 설정돼 있으며, 이는 다음 GC 주기가 되기 전에 최대 3번 시간이 지나야 한다는 뜻이다.
- Desired survivor size가 4194304바이트라는 것은 SurvivorRatio=2를 통해 결정되었다. 이는 Eden/Survivor space=2로 지정한 것이다. 신세대의 heap 크기가 24MB이면, 24MB=2*Survivor space+Survivor space+Survivor space 또는 Survivor space=8MB를 뜻한다. 기본값인 TargetSurvivorRatio=50의 희망 생존 크기는 8*.5=4MB이다. - 애플리케이션 시작을 시점으로 이 GC가 실행된 시간은 311.649초이다. - 이 GC가 신세대에서 만든 멈춤 시간은 0.1334940초이다. - GC를 하기 전에 사용중이던 신세대의 크기는 21647K이다. - GC를 한 후 사용되는 신세대의 크기는 5312K이다. - 신세대에서 377334K-362736K=14598K의 데이터가 GC되었다. - 21647K-5312K-14598K=1737K가 구세대로 승진되었다. - GC를 하기 전에 사용되고 있던 총 heap 크기는 377334K이었다. - GC를 한 후에 사용되고 있는 총 heap 크기는 362736K이다. - GC를 하기 전에 구세대에 사용중인 heap 크기는 377334K-21647K= 355687K이었다. - GC를 한 후 구세대의 사용하는 heap 크기는 362736K-5312K= 357424K이다. - 이 GC에 구세대로 승진한 객체의 총 크기는 357424K-355687K=1737K이다. - ParNew 표기는 신세대에 Parallel collector를 사용했다는 것을 나타낸다. 기본인 Copying collector를 사용하면 ParNew 대신 DefNew로 표기한다.
verbose:gc 로그 형식에서 사용된 관례는 특정 세대에 대한 보고가 있다면 그 세대의 이름이 우선시되어 보고될 것이다.
[GC [gen1 info1] [gen2 info2] info] |
info는 GC의 일반적인 것이고, 신세대와 구세대를 합한 것이다. info<n>는 gen<n>에 한정돼 있다. 그러므로 각 괄호의 배치를 잘 봐야 할 것이다. | | 구세대 GC
CMS Collector 구세대에서 concurrent mark-sweep collector를 사용하는 것을 스냅샷한 것이다. 앞서 언급했듯이 이 부분은 4단계로 나눠진다. 513.474: [GC [1 CMS-initial-mark: 335432K(491520K)] 340897K (516096K), 0.0482491secs] |
- stop-the-world인 initial mark 단계는 0.048초 걸렸다. - 애플리케이션 시작 시점에서 513.474초에 시작되었다. - 사용중이었던 구세대의 heap 크기는 335432K이다. - 신세대에서 사용하는 heap을 포함한 총 사용중인 heap 크기는 491520K이다. - 구세대의 heap 총 크기는 340897K이다. - 신세대 heap을 포함한 총 heap 크기는 516096K이다. - 이 단계는 메모리를 재순환하지 않는다. - ‘[GC’ 접두사는 stop-the-world 단계를 뜻한다. 513.523: [CMS-concurrent-mark-start] 514.337: [CMS-concurrent-mark: 0.814/0.814 secs] 514.337: [CMS-concurrent-preclean-start] 514.36: [CMS-concurrent-preclean: 0.023/0.023 secs] |
이 concurrent mark 단계는 일초(0.814 + 0.023초)도 걸리지 않았다. 그러나 GC와 함께 애플리케이션도 동시에 실행되었다. 이 단계 또한 어떠한 가비지도 컬렉션되지 않았다. 514.361: [GC 514.361: [dirty card accumulation, 0.0072366 secs] 514.368: [dirty card rescan, 0.0037990 secs] 514.372: [remark from roots, 0.1471209 secs] 514.519: [weak refs processing, 0.0043200 secs] [1 CMS-remark: 335432K(491520K)] 352841K(516096K), 0.1629795 secs] |
- stop-the-world인 remark 단계는 0.162초 걸렸다. - 구세대에 사용중이던 heap 크기는 335432K이다. - 구세대의 총 heap 크기는 491520K이다. - 신세대를 포함한 총 사용중이던 heap 크기는 352841K이다. - 신세대를 포함한 총 heap 크기는 516096K이다. - 이 단계에서 어떠한 메모리도 재순환되지 않는다. - 이미 말했듯이 ‘[GC’ 표기는 stop-the-world 단계라는 것을 알려준다. 514.525: [CMS-concurrent-sweep-start] 517.692: [CMS-concurrent-sweep: 2.905/3.167 secs] 517.693: [CMS-concurrent-reset-start] 517.766: [CMS-concurrent-reset: 0.073/0.073 secs] |
이 concurrent sweep은 3초 걸렸다. 그러나 여러 프로세스가 있는 시스템에서 이 단계는 GC와 함께 애플리케이션 쓰레드가 실행될 수 있다. 4개의 CMS 단계에서 이 단계만이 heap을 스위핑하고 컬렉션한다. | | Default Mark-Compact Collector 만약 CMS collector 대신에 구세대에서 기본인 mark-compact collector가 사용되었다면 GC 스냅샷은 다음과 같을 것이다. 719.2: [GC 719.2: [DefNew: 20607K->20607K(24576K), 0.0000341 secs]719.2: [Tenured: 471847K->92010K(491520K), 2.6654172 secs] 492454K->92010K(516096K), 2.6658030 secs] |
- GC가 시작한 시작은 애플리케이션 시작 시점으로 719.2초였다. - DefNew 표기는 신세대에서 기본인 copying collector가 사용되었음을 알려준다. - ‘[GC’ 표기는 JVM이 stop-the-world GC를 사용했다는 것을 나타낸다. 구세대의 GC에서, 애플리케이션에서 System.gc()를 통해 시스템에 GC를 요청할 수 있는데, 이것은 ‘Full GC’로 표기된다. - 신세대의 총 heap 크기는 24576K이다. - 신세대에서 컬렉션은 단지 시도만 이뤄졌다. 구세대에서 잠재적인 데이터를 모두 흡수할 수 있다는 보장이 없어 컬렉션할 수 없다는 것을 알았기 때문이다. 그 결과 신세대의 컬렉션은 일어나지 않았고, 신세대에서는 어떠한 메모리 재순환도 이뤄지지 않았다고 보고했다(순간의 ms 내에 종료했다는 것을 주시한다). 이는 신세대에서 컬렉션이 이뤄지지 못한다는 것을 결정하는 것 외에는 별달리 한 것이 없기 때문이다. [DefNew: 20607K->20607K(24576K), 0.0000341 secs] |
신세대에서 승진되는 것을 흡수하지 못해 구세대가 꽉 찼기 때문에 GC가 필요하다는 알게 되었다. 그래서 full mark-compact collection이 실행되었다.
- 보유하고 있는 표기는 구세대에 full mark-compact GC가 실행되었다는 것을 나타낸다. ‘구세대’는 ‘Tenured generation’이라고도 한다. - GC를 하기 전에 구세대의 사용중인 heap 크기는 471847K이었다. - GC 후의 구세대의 사용 heap 크기는 92010K이다. - GC가 실행될 때의 구세대의 총 heap 크기는 491520K이었다. - GC 전에 신세대와 구세대의 합인 총 사용중인 heap 크기는 492454K이었다. - GC 후에 신세대와 구세대의 합인 총 사용 heap 크기는 92010K이다. - GC를 통해 컬렉션된 총 크기는 492454K-92010K=399837K이다. - JVM의 총 heap 크기는 516096K이다. - 이 GC로 총 2.6658030초동안 애플리케이션이 중지되었다. |
|