[GC] CMS-concurrent GC Log Term 설명

Sample 예제

1682127.667: [GC [1 CMS-initial-mark: 4198606K(4562944K)] 4336629K(6590464K), 10.9210640 secs] [Times: user=0.28 sys=0.07, real=10.92 secs] 1682138.588: [CMS-concurrent-mark-start] 1682208.512: [CMS-concurrent-mark: 69.823/69.910 secs] [Times: user=6.77 sys=0.61, real=69.91 secs] 1682208.512: [CMS-concurrent-preclean-start] 1682208.746: [CMS-concurrent-preclean: 0.234/0.234 secs] [Times: user=0.05 sys=0.00, real=0.24 secs] 1682208.746: [CMS-concurrent-abortable-preclean-start]  CMS: abort preclean due to time 1682213.805: [CMS-concurrent-abortable-preclean: 4.257/5.058 secs] [Times: user=4.38 sys=0.00, real=5.06 secs] 1682213.807: [GC[YG occupancy: 635718 K (2027520 K)]1682213.807: [Rescan (parallel) , 0.4492060 secs]1682214.256: [weak refs processing, 55.8295440 secs] [1 CMS-remark: 4198606K(4562944K)] 4834325K(6590464K), 56.2833650 secs] [Times: user=1.83 sys=0.00, real=56.27 secs]

CMS Concurrent GC Log 내용에 대한 자그만한 정리.

기본적으로 Serial GC와 CMS GC의 Policy가 다르기 때문에 쌓이는 로그 모습도 매우 다르다. 실시간적으로 GC 대상을 mark하고clean을 하는 CMS GC의 sample은 위의 예제와 같다.

CMS-initial-mark -> CMS-concurrent-mark-start -> CMS-concurrent-mark -> CMS-concurrent-preclean-start -> CMS-concurrent-preclean (-->CMS-concurrent-abortable-preclean-start (  시간이 오래걸릴경우 중간에 정지됨 )

이 로그를 Sample로 잡은 이유가 있다.

이 로그를 잘 보면, user/sys 시간은 굉장히 짧은데 real 시간이 상대적이 매우 길다. 그럼 과연 각각의 의미는 무엇일까?

======================================================================================

user = This is only actual CPU time used in executing the process
sys  = CPU time spent in system calls within the kernel
real = wall clock time.
       In detail, The time should generally be similar to the sys+user time but if the process is blocked or waiting then it would be higher. For example) I/O, blocked CPU and swapping.

======================================================================================

다시 말하면, user/sys 시간이 짧다면 real도 시간이 그리 크게 차이가 나면 안되는 것이다. 그리고 CPU에서 처리하는 시간은 짧은 데 I/O나 CPU block  시간이 길다는 이야기이다. 보통 이럴경우에는 물리 메모리가 부족해서 swapping이 일어나거나 당시에 CPU usage가 치솟았는지를 확인해봐야한다.