유용한 JVM 플래그들 – Part 8 (GC Logging)

이 씨리즈의 마지막은 가비지 컬렉션 로깅과 연관된 플래그들이다. GC 로그는 힙의 잠재적인 개선, GC설정 이나 애플리케이션의 객체할당 패턴을 들어내주는 아주 중요한 툴이다. 각 GC가 발생하면, GC 로그는 과정과 결과에 대한 정밀한 데이터를 제공한다.

-XX:+PrintGC

-XX:+PrintGC 나 혹은 별명인 -verbose:gc 는 모든 young generation GC와 모든 풀GC에 대해 라인으로 출력되는 단순히 GC 로깅 모드를 활성화한다. 예를들면 다음과 같다.

라인의 시작은, ‘GC’ 혹은 ‘Full GC’, GC 타입이다. 그 다음이 GC 전과 후에(화살표로 구분되는) 점유 힙 메모리고 괄호안에 용량은 현재 힙의 용량이다. 라인의 끝은 GC가 수행된 시간이다(초단위 시간).

따라서, 첫째라인에서, 246656K→243120K(376320K) 는 GC가 점유 힙 메로리를 246656K 에서 243120K 로 줄였다는 뜻이다. GC 당시에 힙 용량은 376320K 이고 GC 는 0.0929090 시간을 소비했다.

단순한 gC 로깅 포캣은 사용되는 GC 알고리즘과 아무런 상관이 없고 더이상 상세함을 제공하지 않는다. 위의 예제에서 우리는 GC가 young 에서 old generation 으로 객체가 이동될때에 로그에 기록할 수 없다. 그러한 이유로, 상세한 GC 로깅은 단순한 로깅보다 훨씬 유용하다.

-XX:+PrintGCDetails

만약 -XX:+PrintGC 보다 -XX:+PrintGCDetails 를 사용한다면, 우리는 사용되는 GC 알고리즘에따라 달라지는 “상세한” GC 로깅 모드를 활성화 한다. 처리량 컬렉터를 사용하는 young generation GC 에 의해서 생성된 출력을 살펴보는 것으로 시작한다. 좀 더 읽기 편하게, 나는 출력물을 몇개의 라인으로 나누고 그들을 들여쓰기를 했다. 실제 로그에서, 이것은 한줄이며 사람이 읽기는 불편하다.

우리는 단순한 GC 로그로부터 몇가지 요소를 알수 있었다. 점유 힙 메모리를 246648K 에서 243136K 감소시키고 0.0935090 초를 소비한 young generation GC가 있다. 추가로, young generation 자체에 대한 정보를 얻는데, 이것의 용량과 점유률뿐만아니라 사용된 컬렉터가 무엇인지를 알 수 있다. 위 예제에서, “PSYoungGen” 컬렉터는 점유된 young generation 힙 메모리가 142816K 에서 10752K 로 줄일 수 있었다.

우리는 young generation 용량을 알고 있기 때문에, young generation 이 다른 객체할당을 수용할 수 없기때문에 GC를 발생시켰다라고 쉽게 이야기할 수 있다. 활용가능한 142848K 중에 142816K 이 사용되었다. 게다가, 우리는 우리는 young generation에서 제거 된 개체의 대부분이 아직 살아 있고 old generation 으로 이동되었다고 결론 내릴 수 있다: 142816K→10752K(142848K) 와 246648K→243136K(375296K) 를 비교해 young generation 이 거의 완벽하게 비였음에도 불구하고, 전체 힙 점유률은 거의 같게 남았다.

상세 로그 섹션의 “Times”은 GC에 의해서 사용된 운영체제의 커널 공간(“sys”), 사용자 공간(“user”)으로 나뉜 CPU 시간에 대한 정보를 포함한다. 또, GC가 동작중에 소비한 real time(“real”) 가 보인다. (0.09 sms 로그에서 보여준 0.0935090 시간의 반올림일 뿐이다.) 만약 위 예제처럼 CPU time 이 소비된 real time 보다 상당히 높다면 GC가 다중 쓰레드를 사용해 동작했다고 결론내릴 수 있다. 이러한 경우, 기록된 CPU time 은 모든 GC 쓰레드들의 CPU time의 총 합이다. 그리고 추가로, 나는 위 예제에서 컬렉터가 8개의 쓰레드를 사용했다고 말할 수 있다.

이제 풀GC 출력에 대해서 생각해보자.

young generation 에 대한 추가된 상세함으로 인해서 old 와 permanert generation 에 대해 상세함을 우리에게 제공해준다. 전체 세가지 세대들에 대해, 우리는 사용된 컬렉터, GC 전후에 점유율, GC 시에 용량을 알 수 있다. 주목할 것은 총 힙에 대해 보여준 각 숫자는 ( 243136K→241951K(628736K) ) 는 young 과 old generation 의 숫자 합과 같다. 위 예제에서, 241951K 의 총 힙을 점유했고 9707K 는 young generation, 232244K 는 old generation 을 점유했다. 풀GC는 1.53초 소비됐고 user space에서 CPU time 10.96 초는 GC가 다중 쓰레드로 상되었음을 보여준다.(위와같이 8개 쓰레드)

다른 세대들에대한 상대한 출력은 GC 발생에대한 추론을 가능하게 한다. 만약에, 모든 세대에 대해, GC전에 점유한 로그 상태가 거의 현재 용량과 같다면 이 세대는 GC가 발생가능성이 높다. 하지만, 위 예제에서, 이것은 세가지 세대에대해 해당되지 않는다. 그러면 무엇이 이 경우에 GC를 발생시켰을까? 처리율 컬렉터에서 GC 인체공학이 세가지 세대중에 하나가 고갈되기전에 GC가 이미 실행되어야 한다고 결정했다면 실제로 이러한 일이 발생될 수 있다.

풀GC 또한 애플리케이션이나 외부 JVM 인터페이스중에 하나를 통해서 명시적으로 요청이 있을때에 발생될 수도 있다. “system GC” 경우에는 GC 로그에서 “Full GC” 대신에 “Full GC(System)”으로 시작되는 라인을 가지기 때문에 쉽게 파악할 수 있다.

시리얼 컬렉터(Serial Collector) 에서, 상세 GC 로그는 처리량 컬렉터와 매우 유사하다. 한가지 다른 점이라면 다른 GC 알고리즘을 사용하고 있기 때문에 다양한 섹션들에 이름들이 다르다.(예를들어, old generation 섹션은 “ParOldGen” 대신에 “Tenured” 라 부른다). 정확한 이름의 컬렉션을 사용하는 것이 좋은데, JVM의 의해서 사용되어지는 특정 가비지 컬렉션의 로그로부터 추론을 할 수 있기 때문이다.

CMS 컬렉터(CMS Collector)에서, young generation GC에 상세 로그는 역시 처리량 컬렉션과 매우 유사하지만 old generation GC에 대해서는 같지 않다. CMS 컬렉터에서 old generation GC들은 다른 단계를 사용해 애플리케이션에 동시적으로 작동한다. 그렇기 때문에, 그것의 출력은 풀GC 출력과 다르다. 추가적으로 다른 단계에대한 라인들은 일반적으로 동시적 컬렉션이 동작중에 발생된 young generation GC 에대한 라인에 의해서 로그와 분리된다. 다른 컬렉터들을 이미 봐왔기 때문에 GC 로그의 모든 요소들이 익숙하고 그래서 다른 단계에 대한 로그를 이해하기란 어렵지 않다. 다만 처리중일때에 특별히 조심하고 애플리케이션과 동시적으로 모든 단계가 실행된다는 것을 상기해야만 한다. 따라서, 반대되는 stop-the-world 컬렉션들처럼, 개별적인 단계 혹은 전체 GC 주기가 오랫동안 실행되는 시간이 항상 문제가 있다는 것은 아니다.

이 시리즈의 part 7에서 알아봤듯이, 풀GC들은 CMS 컬렉터가 재시간에 CMS 주기가 완료되지 않으면 발생 될 수 있다. 만약 그게 발생하면, GC 로그는 추가적으로 풀GC 발생 원인이 무엇인지와 같은 힌트를 포함한다. 예를들어, “concurrent mode failure” 와 같은.

이 기사를 짧게 유지하기 위해서, 나는 CMS 컬렉터 GC 로그의 상세한 설명을 자제할 것이다. 또, 실제 컬렉터 작성자중에 한분이 여기에 이미 훌륭한 설명을 발표했다. 나는 이것을 읽기를 강력히 추천한다.

-XX:+PrintGCTimeStamps and -XX:+PrintGCDateStamps

이것은 (단순하게 혹은 상세하게) GC 로그에 시간과 날짜 정보를 추가하는게 가능하다. -XX:+PrintGCTimeStamps 에서 timestamp 은 JVM이 시작된 이후에 초단위로 흐른 실제시간을 반영하도록 매 라인마다 추가된다. 예를들어

그리고 -XX:+PrintGCDateStamps 를 지정하면 로그가 쓰여질때에 각 시작 라인이 절대 날짜와 시간을가지고 시작된다.

두가지 출력이 좋아보이면, 두 플래그 조합이 가능하다. 나는 항상 두가지 플래그를 지정하도록 권하는데, 그러한 정보는 다른 소스들로부터 데이터를 가지는 GC 로그 데이터를 연관시키기위해 매우 유용하다.

-Xloggc

기본적으로 GC 로그는 stdout 에 쓰여진다. 대신 -Xloggc:<file> 로 우리는 출력 파일을 지정할 수 있다. 주목할 것은 이 플래그는 -XX:+PrintGC 과 -XX:+PrintGCTimeStamps 처럼 묵시적으로 지정한다. 역시, 나는 필요하다면 이러한 플래그들을 명시적으로 지정하길 권하는데, 새로운 JVM 버전들에 예기치않은 변화로부터 여러분들로부터 보호해준다.

“Manageable” Flags

자주 논의되는 것중에 프로덕트 시스템에 JVM에 GC 로깅을 활성화해야하느냐 마느냐 하는 것이다. GC 로깅의 오버헤드는 보통 매우 적다라는데 나는 분명히 “yes”다. 하지만, 이것은 JVM이 시작할때에 우리는 GC 로깅에 대한 고민을 할 필요가 없다건 좋은 것이다.

HotSpot JVM 은 “manageable”이라 불리우는 특별한(하지만 아주 작은) 카테고리 플래그들을 가진다. 관리 플래그들에 대해 런타임으로 그들의 값을 변경하는 것이 가능하다. 여기서 논의한 모든 플래그들과 “PringGC” 로 시작하는것들이 “manageable” 카테고리에 속한다. 따라서, 우리는 실행중인 JVM에서 우리가 원할때마다 언제든지 GC 로깅을 활성화하거나 비활성화할 수 있다. 관리 플래그들을 지정하기 위해서 우리는 JDK에 포함된 jinfo 를 사용하거나 JMX 클라이언트와 HotSpotDiagnostic MXBean 의 연산인 setVMOption를 호출해 가능하다.