잊지 않겠습니다.

Java VM - YoungGen space의 동작

번역(http://javaeesupportpatterns.blogspot.ie/2013/11/java-vm-beware-of-younggen-space.html) 입니다. 약간의 의역과 오역이 들어가있을수 있습니다. ^^;

정상적인 JVM 상태는 application의 성능 및 안정성에 매우 중요한 목표라고 할 수 있다. 이러한 health 평가는 GC의 major collection이나 memory leak에 촛점이 맞춰져 있다. Young Generation space 또는 shot lived object의 경우에는 크기나 저장 공간이 어떻게 될까?

이 article은 우리의 client의 최신 장애 경험에 의거한 이야기이다. 샘플 application을 통해, 이 현상을 보여줄 것이며, 메모리 저장소와 minor collection이 Old Generation collection 또는 tenured space와 비슷한 정도의 성능저하를 나타낼 수 있음을 보여줄 것이다.

JVM Health diagnostic

만약에 당신이 JVM tunning의 신참이라면, 모든 application에 공통으로 사용할 수 있는 일반적인 솔루션은 존재하지 않는다는 것은 곧 알 수 있을 것이다. Web을 통한 여러 소스의 경로를 통해, 여러분들은 JVM GC pauses가 매우 섬세하며 이것을 이해하기 위해서는 매우 많은 노력을 해야지 된다는 것을 알 수 있다. (어떤 application은 JVM pause time을 1% 이하로 줄이길 요구한다.)

성능과 load testing을 같이 하는 Java profiling (메모리 leak detection을 포함)은 JVM runtime health와 당신의 application의 memory 저장공간에 대한 데이터와 시실을 모두 수집하기 위한 좋은 방법이 된다.

그럼, “Healthy” JVM 이란 무엇을 의미하는가? 이 질문에 대해서 당신의 최고의 지식을 가지고 다음 질문들을 대답해보길 바란다.

만약에 당신이 NO라고 대답한다면, 90%이상의 확신을 가진 대답을 해주면 된다. 또는 I DON’T Know 라고 해도 된다.

  • Application에서 Java heap 또는 OldGen space leaking over time이 발생하는가? (major collection이 발생한 경우)
  • Application에서 현재 크거나 잦은 JVM GC Collection이 발생하고 있는지?
  • JVM overall pause time이 5%보다 넘거나 이상적인 baseline보다 높은지?
  • Application의 response time이 JVM GC 행위에 영향을 받고 있는지?
  • 3개월 내로, java.lang.OutOfMemoryError error를 경험해본적이 있는지?
  • 3개월 내로, JVM의 crush 현상을 격어본적이 있는지?
  • 당신의 JVM 상태가 현제 불안정하거나 인위적인 개입을 받아야지 되는 상태에 있는지? (JVM reboot etc.. )

만약에 당신이 YES 또는 I don’t know라고 대답을 했다면, 당신의 production 성능을 높이기 위해서 tuning team이 현 JVM GC policy를 살펴서 해야지 될 일들이 남아있다는 것이다.

만약에 당신이 모든 질문에 NO라고 대답할 수 있다면, 당신은 매우 견고한 application과 JVM 안정성을 가지고 있는 것이다. 축하한다. 여전히 나는 당신에게 major release와 load forecasts에 대한 상황을 평가하는 것을 제안한다.

Young Generation : Stop-The-World

우리가 JVM Health 평가를 진행할 때, JVM overall pause time은 자주 언급되는 문제이다. JVM overall pause time은 JVM이 stop the world event가 발생할 때, 얼마나 많은 시간이 걸리는지를 측정하는 것이다. Event가 발생중에, application thead는 모두 중지되고, 어떠한 일도 동작하지 않으며, application의 응답시간은 증가되게 된다. 이 수치는 JVM의 불안정성 이나 예측 불가능한 응답시간에 대한 매우 중요한 지표로 사용된다.

최근 몇년을 거쳐 사람들이 많이 알고 있으나, 잘못된 정보는 YoungGen 또는 minor collection은 매우 명료하며, application response time에 영향을 주지 않는다.라는 선입관이다. 이 문장은 대부분의 경우에 참이지만, Java heap size가 작고 (YG space < 1GB), 생명주기가 매우 짧은 경우만을 한정해야지 된다. 위 시나리오는 minor collection 실행이 매우 빠르며 (< 20msec), 자주 일어나지 않으며 (every 30 seconds++), overall JVM pause 시간중 YoungGen space가 매우 작게 남아있는 경우이다(<< 1%). 그러나, YG memory 할당 빈도수는 매우 빠르게 증가되어 이러한 상황은 매우 쉽게 변화될 수 있다(traffic의 증가로 인하여 사용자가 증가하는 경우, YG의 Size 및 할당 빈도수는 매우 쉽게 증가한다).

다음 article에서 제안한 내용을 중심으로 YoungGen space와 concurrent collectors에 대한 정보를 좀 더 얻기를 바란다.

Oracle HotSpot mostly concurrent collectors: CMS vs. G1

http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html

Oracle HotSpot minor collections exhaustive coverage

http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html
http://blog.griddynamics.com/2011/06/understanding-gc-pauses-in-jvm-hotspots_02.html

이미 사용하고 있는 HotSpot GC 규정에 상관없이, 모든 collector들 CMS, G1, YoungGen space collection 모두는 “stop the world”를 발생시킬 수 있다. 우리의 지식대로, Azul Zing C4만이 실시간 compacting collectior인 것으로 알려지고 있다. 우리는 현 시점에서 이 collector를 사용할 수 있는 경험을 갖지 못했다. C4 tuning 경험이나 연구 결과가 있다면 많은 공유를 부탁드린다.

지금 우리는 약간의 이론을 소개하도록 한다. sample application을 통해, 성능 검사 결과는 다양한 YoungGen의 저장공간과 할당 빈도를 보여줄 것이다.

Sample application specification

YG 할당빈도수에 따른 JVM pause time %를 측정하기 위해 우리는 다음 sample application을 작성하였다.

// jvm uri를 갖는 REST WebService (JAX-RS)
@GET
@Path("/jvm")
@Produces(MediaType.APPLICATION_JSON)
public Integer jvm() {}

jvm method의 실행은 다음 로직을 따르게 된다.

이미 결정된 크기의 short-lived object를 할당한다. (fast Young GC의 요건에 적합하다.)

추가적으로, 1 GB의 CMS collector의 동작의 약간의 noise를 가할 목적의 long-lived objects의 저장소를 만들어준다(GC의 대상이 아니다.).

private final static int LONG_LIVED_OBJ_FOOTPRINT = (1024 * 1024 * 1024);
private final static int SHORT_LIVED_OBJ_FOOTPRINT = (100 * 1024 * 1024);

// 1 GB static memory footprint
private final static byte byteArrayLongLivedObj[] = new byte[LONG_LIVED_OBJ_FOOTPRINT];

// 100 MB memory allocation (waste) created per execution
public void generateShortLivedObj(String objId) {          
  byte byteArrayShortLivedObj[] = new byte[SHORT_LIVED_OBJ_FOOTPRINT];
}

마지막으로, 테스팅하는 환경 변수는 다음과 같다.

OS: Windows 7 @64-bit
Java EE container: WildFly 8 Beta1
JVM: Oracle HotSpot 1.7 @64-bit with a Java heap size of 5 GB (YG space: 1152 MB XX:NewRatio=3). GC collector: CMS
IDE: JBoss Developer Studio 7.0.0.GA
JVM monitoring: JVisualVM
JVM memory leak analyzer: Plumbr 3.0
JVM verbose:gc log analyzer: GCMV
Performance & load testing: Apache JMeter 2.9

Performance testing results and observations

Simulated된 성능 테스팅은 높은 JVM pause time을 가지고 있었으며, peak load하에서 잦은 성능저하를 보여줬다.

Baseline

  • 10개의 concurrent thread
  • JVM process당 100 MB의 short lived object.

short lived object memory 저장 공간은 매우 극적이지만, 처음에는 잘 운영되었다.

Result

Average response time: 140 ms
Throughput: 68 req / sec
JVM overall pause time: 25.8%
YG collection frequency: 7 collections per second
Rate of GC: 308,909 MB per minute

JvirtualVM에 따르면, 이 JVM은 정상적이다(memory leak이 없으며, 안정적이며, OldGen collect 횟수가 낮다). 그러나, verbose:gc log를 좀 더 깊게 바라보면, JVM pause time이 전체 runtime 시간의 25.8%가 되는 것을 알 수 있고, 모든 지연시간은 YG Collection에 의해서 발생됨을 알 수 있다. 이것은 명확하게 verbose:gc log vs JVM에 대한 검증된 기준과의 차이에 대한 적절한 분석이 필요함을 보이고 있다.

Test & tuning #1.

  • 10 concurrent threads
  • 50 MB of short lived objects / JVM process

(먼저번의 테스트와의 차이점은 short lived object의 크기가 다르다는 점이다.)

위 조건에서 application의 메모리 할당 용량은 100MB에서 50MB 사이에서 동작하고 있었다. 우리는 명확히 개선된 것을 모든 지표에서 볼 수 있었으며 request 당 할당되는 메모리 양의 감소가 처리양에 관련이 있는 것을 볼 수 있다.

Result

Average response time: 119 ms  -21
Throughput: 79 req / sec  +11
JVM overall pause time: 15.59%  -10.21
YG collection frequency: 3-4 collections per second  -3
Rate of GC: 164 950 MB per minute  -143 959

Test & tuning #2

  • 10 concurrent threads
  • 5 MB of short lived objects created per execution per JVM process

(Test 1에 비하여 request 당 생성되는 short lived object의 크기가 5M로 반으로 줄었다.)

Result

Average response time: 107 ms  -33
Throughput: 90 req / sec  +22
JVM overall pause time: 1.9%  -23.9
YG collection frequency: 1 collection every 2-3 seconds * significant reduction
Rate of GC: 15 841 MB per minute  -293 068

보는것과 같이, application footprint와 memory 할당에 대한 최종 개선은 의미있는 매우 적절한 1.9%정도인 JVM pause time을 보여주고 있다.3번의 테스트를 통해서 매우 중요한 점을 알 수 있는데, OldGen footprint와 CMS 동작은 JVM pause time에 전혀 영향을 주지 않고 있으며, 성능 문제는 과도한 동작과 YG Collection에 연결된 매우 큰 크기의 stop the world event와 연결되어 있음을 알 수 있다.

Solution & recommandations

이 문제 케이스에서 우리는 JVM pause time을 줄이기 위해서는 연관된 과도한 YG collection 활동에 대한 tuning과 application request에 의한 memory footprint를 제거시켜주는것이 중요함을 알 수 있다. 따라서, application rate와 YG GC frequency를 줄이는 것이 중요하다.

그러나, 이러한 tuning 전략은 단기간에 가능하지 않는데, 다른 솔루션들을 분석하는 것이 더욱더 가치가 있기 때문이다. 이와 유사한 결과는 어쩌면 다음과 같은 허용량 개선 전략으로도 성취할 수도 있다.

  • Horizontal & Vertical scaling : traffic을 증가된 숫자의 JVM process로 나누면 메모리 할당 빈도와 YG Collection 횟수를 줄일 수 있다. 이는 근본적인 원인을 hardware로 넘기는 방법이다. 나의 추천사항은 언제나 당신의 application memory footprint를 먼저 tunning하고, 다른 scaling option을 찾는 것이다.
  • Java heap size & YG ratio tuning : YG 영역의 크기의 증가는 틀림없이 YG Collections에 의한 frequency를 줄일 수 있다. 그러나 매우 주의해야지 된다. 절대로 OldGen space를 굶주리게 만들어서는 안된다 그렇지 않으면 당신은 매우 간단히 문제를 JVM thrashing과 OOM events쪽으로 옮겨버리게 된다.

Final words

JVM YG collections의 성능 영향에 대해서 보다 나은 이해가 있기를 바란다. 나는 이 article을 읽은 후에 다음과 같은 실습을 해보기를 권합니다.

  • 당신이 맡고 있는 가장 바쁘게 돌아가는 application을 선택합니다.
  • verbose:gc log를 살펴보고, JVM pause time과 GCMV를 결정해보세요.
  • YG collection에 의한 영향을 판단하고, tunning 기회를 알아보시길 바랍니다.

당신의 comment와 JVM tuning 경험 기회를 공유할 수 있기를 바랍니다.


Posted by Y2K
,