태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

'Enterprise Java'에 해당되는 글 34건

  1. 2007.10.19 [Sun Java Forum] PretenureSizeThreshold의 의미... (1)
  2. 2007.10.03 Sun Java Forum - HotSpot 최적화에 의한 착각...
  3. 2007.10.03 Java에서의 Out Of Memory Error(OOME)에 대한 나름대로의 정리... (5)
  4. 2007.09.22 Sun Java Forum - 잘못된 Young Generation 크기에 의한 Full GC 발생
  5. 2007.09.19 한국은 왜 Software의 변두리에만 머물러 있을까... (3)
  6. 2007.09.18 JMP - 공짜치곤 괜찮은 Java Profiler
  7. 2007.09.18 [Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part4
  8. 2007.09.13 [Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part3
  9. 2007.09.12 [Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part2
  10. 2007.09.10 [Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part1 (3)

[Sun Java Forum] PretenureSizeThreshold의 의미...

Enterprise Java 2007.10.19 23:39
PretenureSizeThreshold 옵션을 사용해본 사람이 있는지 모르겠다.
이 옵션은 Object를 Young Generation을 거치지 않고 Old Generation에 직접 저장하는 기능을 활성화한다.
가령 이 값이 1000이면 1000바이트 이상되는 Object들은 Old Generation으로 직접 들어가게 된다.
왜 이런 옵션을 사용할까?
  • 특정 크기 이상의 Object가 Long-Lived, 즉 장수하고 있다는 사실을 미리 알고 있다면...
  • 이런 Object들을 Young Generation에 살게 했다가 나이가 들면 다시 Old Generation으로 옮기는 일련의 과정이 오버헤드가 된다.
  • 따라서 PretenureSizeThreshold 옵션을 사용하면 이런 오버헤드를 줄일 수 있다.
상당히 좋은 기능이다.
하지만, Application을 작성해본 사람은 다 알겠지만, 이렇게 심플한 상황이 어디 흔한가? 크기가 큰 객체도 단명(Short Lived)하는 경우가 비일비재하다. 그런 경우에 이 옵션을 사용했다가는 마치 암 환자를 요양소에 밀어 놓는 꼴이고, 불필요한 Full GC를 유발하게 된다.

아래 글이 이런 내용에 대해 논의를 하고 있다.
이런 옵션을 사용하고 또 이런 내용이 공개적으로 토론이 된다는 사실이 부러울 뿐이다.
(아래 Dion_Cho 가 본인...)

혹시 이 글을 읽는 사람들 중에 CMS Collector를 사용하고 있는 사람은 얼마나 되는지 모르겠다.
언젠가 한번 설문조사를 해보아야 할 듯 하다...


DiegoCarzaniga
Posts:109
Registered: 12.01.06
Using -XX:PretenureSizeThreshold
Oct 17, 2007 2:56 AM

Hi guys,

I hava a question about Gargabe Collector tuning.

My real time application generates every second (with a certainquantity of traffic) some objects with long time life (MEMORY_OLD), andsome with short long life (MEMORY_YOUNG).

After a code review I reduced the quantity of objects created, in orderto optimize GC pauses and frequency. The ratio MEMORY_YOUNG/MEMORY_OLDis augmented to about 3.3.

With this ratio i choose these JVM options:
-Xmx1024m -Xms1024m -XX:MaxNewSize=16m -XX:NewSize=16m

The problem is that with a so high MEMORY_YOUNG/MEMORY_OLD ratio, everyGC young copies many objects to Tenured space... this augments GC YOUNGpauses to about 70 ms. To make smaller these pauses I could sizesmaller -XX:MaxNewSize, but in this way GC young frequency will augmenttoo much causing problems during CMS phases.

So I though about -XX:PretenureSizeThreshold option that copies objects bigger than defined size, directly into Tenured Space.
Does something know if this option can be useful in this scenario?
Tuning it with the right size could be avoid unnecesary promotion toTenure Space... but on the other side it will copy to tenured spacealso objects that otherwise will die in Eden space at the first GCYoung.

Can anyone give me some advice?

Thank you very much all in advance
Diego
Dion_Cho
Posts:60
Registered: 9/6/07
Re: Using -XX:PretenureSizeThreshold
Oct 18, 2007 6:11 AM (reply 1 of 2)

1. Young generation = 16M? Is this just mistake or really 16M? Don'tyou think young generation size is way too small? Especially when yourjava heap size is 1G?
I'm not quite sure about the structure of your app... But, if younggeneration size is this too small, minor gc occurs too frequently andmore objects would be promoted to old generation without any chance tobe collected(as you told yourself in original post)

You can try -XX:+UseParNewGC with bigger young generation size if you're on multiple CPU.
(You may be already turning this option on in recent version...)

2. If you're worried about stop-the-world full gc under CMS collector,you can tweak following options: CMSInitiatingOccupancyFraction,CMSIncrementalMode, UseCMSInitiatingOccupancyOnly, ...
Consult JVM garbage collector tuning guide for more info.

3. PretenureSizeThreshold option exactly matches your request. Justwant to check one thing. Is your big object is a real "one" bigobject(like big array) or just a set of small objects? In latter case,it would not go directly to tenured generation.

Anyway, what JVM version and optionally what OS are you on? Coz every version has its own GC features...

DiegoCarzaniga
Posts:109
Registered: 12.01.06
Re: Using -XX:PretenureSizeThreshold
Oct 18, 2007 7:13 AM (reply 2 of 2)

Thank you Dion_Cho!
My EDEN SPACE is about 16M.... it's not a mistake.
My application is a real time one which needs short stop-the-worldpauses in order to avoid protocol retransmission (which could casecongestion of the application).
So I prefer smaller GC YOUNG pauses.... although in this way GC YOUNG frequency is very high.

I'm using 1.4 JVM on a Sun machine.

I'm already using -XX:+UseConcMarkSweepGC and -XX:+UseParNewGC.

Regard to PretenureSizeThreshold... I tried to set it to 1000 B. Inthis way some big objects can be directly promoted to the TENUREDSPACE. Unfortunately performance didn't improve, probably because inthis way not only old objects, but also some young objects sarepromoted directly.

Thank you again for your reply
Diego


신고
Trackback 0 : Comment 1
  1. FryRachael32 2011.12.01 12:22 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment


Sun Java Forum - HotSpot 최적화에 의한 착각...

Enterprise Java 2007.10.03 23:38
HotSpot JVM의 가장 큰 장점은 "컴파일 최적화"에 있다. 전통적인 JIT 컴파일러의 장점은 그대로 살리면서 단점(늦은 구동시간과 비효율적인 최적화)을 해소하는 것이 HotSpot Compiler의 주 설계 목적이다.

하지만 이 와중에 우리의 시각을 혼란스럽게 만드는 요소가 생긴다.
HotSpot JVM의 지능적이고 자동화된 최적화 기법 때문에 Warming-Up 시간이 필요해진다. 즉 JVM이 바이트코드로부터 최적의 바이트코드나 바이러리 코드를 찾아내는데 일정한 시간이 필요하다. 이 때문에 최초 얼마간의 성능 측정만으로 성능을 좋다 나쁘다를 결정하는 것은 위험할 수 있다.

동일한 구현 방법에 대해서 JVM이 C/C++과 거의 비슷하거나 나은 정도의 성능을 내는데 10분 정도의 시간이 소요되었다는 연구 결과를 본 적이 있다.

아래 논의도 비슷한 내용을 담고 있다. 분명이 성능이 더 좋아야 할 코드가 실제로는 나쁜 성능을 보이는 이유에 대해서 논의한 결과이다. 잠정적인 결론은 HotSpot JVM이 최적의 코드를 생산해내는데 걸리는 Warming-Up 시간으로 인해 초기에는 그런 모순된 결과가 나올 수 있다는 것이다.

섣부른 성능 테스트라는 것이 얼마나 많은 오류를 내포하고 있는지 알 수 있는 기회이기도 하다.

UMTS
Posts:3
Registered: 9/21/07
naive for loops runs faster than "optimized"?
Sep 21, 2007 7:14 AM

well,
I remember certification question (310-025):
what piece of code runs faster:
1.
for(int i=0; i
r = r + s.charAt(i);
}
2.
int l = s.length();
for(int i=0; i
r = r + s.charAt(i);
}

well anybody would say that 2 should be at least not worse than 1. We eliminate repeatable call to length() method of string.
I was really surprised that in 1.6.0 the 1 run is faster (not much but about 10%-15%).
I could understand that method inline-*** could make 1. to be of thesame performance that achieved in 2. but being FASTER than 2 is reallyextraordinary behaviour. Could explain why?

I looked at piece of code (java.util.regex.Mathcer):
/**
* Returns a literal replacement String for the specified
* String.
*
* This method produces a String that will work
* as a literal replacement s in the
* appendReplacement method of the {@link Matcher} class.
* The String produced will match the sequence of characters
* in s treated as a literal sequence. Slashes ('') and
* dollar signs ('$') will be given no special meaning.
*
* @param s The string to be literalized
* @return A literal string replacement
* @since 1.5
*/
public static String quoteReplacement(String s) {
if ((s.indexOf('
') == -1) && (s.indexOf('$') == -1))
return s;
StringBuffer sb = new StringBuffer();
for (int i=0; i
char c = s.charAt(i);
if (c == '
') {
sb.append('
'); sb.append('
');
} else if (c == '$') {
sb.append('
'); sb.append('$');
} else {
sb.append(c);
}
}
return sb.toString();
}
and think that having s.length() as a variable would make code faster,but making small experiment showed me that I might be wrong :(
Dion_Cho
Posts:40
Registered: 9/6/07
Re: naive for loops runs faster than "optimized"?
Sep 21, 2007 9:01 AM (reply 1 of 4)


Hm... weird. My code tells the opposite.

See following:

c:Program FilesJavajdk1.6.0_02bin>java -version
java version "1.6.0_02"
Java(TM) SE Runtime Environment (build 1.6.0_02-b06)
Java HotSpot(TM) Client VM (build 1.6.0_02-b06, mixed mode)

c:Program FilesJavajdk1.6.0_02bin>java -cp . test
1. Elapsed time = 1468 <-- for(int i=0; i
2. Elapsed time = 1156 <-- for(int i=0; i
3. Elapsed time = 1156 <-- for(int i=0; i
4. Elapsed time = 1156 <-- for(int i=0; i<30; i++) s.length() == 30

My test shows that naive loop is slowest and optimized code runs faster. This is natural result.

To make it clear, i recommend you review your test code. If youcan't find any flaw, better post your source code. In that case, mytest code could have flaw.

Anyway, i'm not sure that String.length method is inlined by hotspot jvm.
Hprof shows that: (-Xrunhprof:cpu=times)

rank self accum count trace method
1 50.34% 50.34% 1 303982 test.main
2 31.10% 81.45% 400000 300848 java.lang.String.charAt
3 5.65% 87.09% 102001 300847 java.lang.String.length
4 0.58% 87.67% 12 302704 sun.misc.ASCIICaseInsensitiveComparator.compare
5 0.58% 88.24% 129 302697
...

Here you see String.length method being invoked, which means it's not inlined.

(Note) For String.length inlining, refer to http://java.sun.com/developer/onlineTraining/Programming/JDCBook/perf2.html

====================================================
public class test {

public static void main(String[] args) {

int r1 = 0;
int r2 = 0;
int r3 = 0;

String s = "123456789012345678901234567890";

long startTime = System.currentTimeMillis();

for(int idx=0; idx < 10000000; idx++) {
for(int i=0; i
r1 = r1 + s.charAt(i);
}
}

System.out.printf("1. Elapsed time = %dn", System.currentTimeMillis() - startTime);

startTime = System.currentTimeMillis();

int l = s.length();
for(int idx=0; idx < 10000000; idx++) {
for(int i=0; i
r2 = r2 + s.charAt(i);
}
}

System.out.printf("2. Elapsed time = %dn", System.currentTimeMillis() - startTime);

startTime = System.currentTimeMillis();

for(int idx=0; idx < 10000000; idx++) {
l = s.length();
for(int i=0; i
r2 = r2 + s.charAt(i);
}
}

System.out.printf("3. Elapsed time = %dn", System.currentTimeMillis() - startTime);

startTime = System.currentTimeMillis();
for(int idx=0; idx < 10000000; idx++) {
for(int i=0; i<30; i++) {
r3 = r3 + s.charAt(i);
}
}

System.out.printf("4. Elapsed time = %dn", System.currentTimeMillis() - startTime);
}
}

Edited by: Dion_Cho on Sep 21, 2007 6:24 PM

UMTS
Posts:3
Registered: 9/21/07
Re: naive for loops runs faster than "optimized"?
Sep 22, 2007 12:04 AM (reply 2 of 4)

What you say is just what I would expect, but:
C:alexprototypestringbin>java -version
java version "1.6.0_02"
Java(TM) SE Runtime Environment (build 1.6.0_02-b05)
Java HotSpot(TM) Client VM (build 1.6.0_02-b05, mixed mode, sharing)

C:alexprototypestringbin>java TestA
A: value = 20467200000, elaplsed (seconds): 4.040892348

C:alexprototypestringbin>java TestB
B: value = 20467200000, elaplsed (seconds): 5.67969728

C:alexprototypestringbin>
and code:
public class TestA {

/**
* @param args
*/
public static void main(String[] args) {
String s = "";
for(int j = 0; j<10000; j++) {
s = s + j;
}
long t1 = System.nanoTime();
long r = 0;
for(int j = 0; j<10000; j++) {
for(int i = 0; i < s.length(); i++) {
r = r + s.charAt(i);
}
}
long t2 = System.nanoTime();
System.out.println("A: value = " + r + ", elaplsed (seconds): " + (t2-t1)/1000000000.0);
}

}

-- and B which supposed to be faster --
public class TestB {

/**
* @param args
*/
public static void main(String[] args) {
String s = "";
for(int j = 0; j<10000; j++) {
s = s + j;
}
int l = s.length();
long t1 = System.nanoTime();
long r = 0;
for(int j = 0; j<10000; j++) {
for(int i = 0; i < l; i++) {
r = r + s.charAt(i);
}
}
long t2 = System.nanoTime();
System.out.println("B: value = " + r + ", elaplsed (seconds): " + (t2-t1)/1000000000.0);
}

}

How would you explain that?

But look also at that, I have changed the order of tests in your code:
public class TestTest {

public static void main(String[] args) {

int r1 = 0;
int r2 = 0;
int r3 = 0;

String s = "123456789012345678901234567890";

long startTime = System.currentTimeMillis();

int l = s.length();
for (int idx = 0; idx < 10000000; idx++) {
for (int i = 0; i < l; i++) {
r2 = r2 + s.charAt(i);
}
}

System.out.printf("2. Elapsed time = %dn", System.currentTimeMillis()
- startTime);

startTime = System.currentTimeMillis();

for (int idx = 0; idx < 10000000; idx++) {
l = s.length();
for (int i = 0; i < l; i++) {
r2 = r2 + s.charAt(i);
}
}

System.out.printf("3. Elapsed time = %dn", System.currentTimeMillis()
- startTime);

startTime = System.currentTimeMillis();
for (int idx = 0; idx < 10000000; idx++) {
for (int i = 0; i < s.length(); i++) {
r1 = r1 + s.charAt(i);
}
}

System.out.printf("1. Elapsed time = %dn", System.currentTimeMillis()
- startTime);

startTime = System.currentTimeMillis();
for (int idx = 0; idx < 10000000; idx++) {
for (int i = 0; i < 30; i++) {
r3 = r3 + s.charAt(i);
}
}

System.out.printf("4. Elapsed time = %dn", System.currentTimeMillis()
- startTime);
}
}

and got:
2. Elapsed time = 4140
3. Elapsed time = 922
1. Elapsed time = 1109
4. Elapsed time = 1282

Edited by: UMTS on Sep 22, 2007 12:11 AM

Dion_Cho
Posts:40
Registered: 9/6/07
Re: naive for loops runs faster than "optimized"?
Sep 22, 2007 1:17 AM (reply 3 of 4)

Here goes my result(of your codes):
(my laptop outperforms yours :) )

c:Program FilesJavajdk1.6.0_02bin>java -cp . TestA
A: value = 20467200000, elaplsed (seconds): 2.025779812

c:Program FilesJavajdk1.6.0_02bin>java -cp . TestB
B: value = 20467200000, elaplsed (seconds): 1.90442668

To your suprising, the result is exact opposite of yours.

I think you'd better narrow down your phenomenon.
1. Remove all the codes unrelated to String.length(). Measure the effect of "String.length()" not others
2. Optionally, run profiler using "-Xrunhprof:cpu=times" and check which step is the most time consuming job
3. Optionally, collect gc log using "-XX:+PrintGCDetails -XX:+PrintGCTimeStamps"

PS) Anyway, i think my test code was flawed. Maybe because of theeffect of hotspot jvm optimization. I had seen some researches thathotspot jvm needs almost 10 minutes running time to reach its maximumperformance. It's called "warming up" time, and the exact warming uptime depends on situation.
UMTS
Posts:3
Registered: 9/21/07
Re: naive for loops runs faster than "optimized"?
Sep 24, 2007 3:48 AM (reply 4 of 4)

Seems I got a kind of clue...
I modified the code to run the same piece more times...
public class TestA {
public static void main(String[] args) {
r();
r();
r();
r();
r();
r();
}
public static void r() {
String s = "";
for(int j = 0; j<10000; j++) {
s = s + j;
}
long t1 = System.nanoTime();
long r = 0;
for(int j = 0; j<10000; j++) {
for(int i = 0; i < s.length(); i++) {
r = r + s.charAt(i);
}
}
long t2 = System.nanoTime();
System.out.println("A: value = " + r + ", elaplsed (seconds): " + (t2-t1)/1000000000.0);
}
}

public class TestB {
public static void main(String[] args) {
r();
r();
r();
r();
r();
r();
}
public static void r() {
String s = "";
for(int j = 0; j<10000; j++) {
s = s + j;
}
int l = s.length();
long t1 = System.nanoTime();
long r = 0;
for(int j = 0; j<10000; j++) {
for(int i = 0; i < l; i++) {
r = r + s.charAt(i);
}
}
long t2 = System.nanoTime();
System.out.println("B: value = " + r + ", elaplsed (seconds): " + (t2-t1)/1000000000.0);
}
}
and I got
C:alexprototypestringbin>java TestA
A: value = 20467200000, elaplsed (seconds): 4.029689249
A: value = 20467200000, elaplsed (seconds): 4.058129455
A: value = 20467200000, elaplsed (seconds): 1.603812775
A: value = 20467200000, elaplsed (seconds): 1.603092293
A: value = 20467200000, elaplsed (seconds): 1.605882033
A: value = 20467200000, elaplsed (seconds): {color:#ff0000}1.609466566

C:alexprototypestringbin>java TestB
B: value = 20467200000, elaplsed (seconds): 5.702802171
B: value = 20467200000, elaplsed (seconds): 5.5870017
B: value = 20467200000, elaplsed (seconds): 1.608010236
B: value = 20467200000, elaplsed (seconds): 1.594163784
B: value = 20467200000, elaplsed (seconds): 1.595716215
B: value = 20467200000, elaplsed (seconds): {color:#ff0000}1.595248558

C:alexprototypestringbin>

Now we see that eventually B is faster as everyone would expect...
Butby some reasons optimization of that code tooks a bit longer time thanA... which is strange but understandable (may be optimizer "tried" somemore variants of optimization)...

What strange is that your laptop faster than mine and showed expected behaviour from the very beginning.
I own Toshiba P105-6114, 1GB processor T5500 (dual core), what isyours? May be having 2 processors slows optimization down for a while?

Concerning naive versus optimezed I dare say that effectof optimization is close to 0, and seems I know why... String is afinal class more over it is a class with well-known behaviour:optimizer could asume that length() always produce the same value andthere is no reason to "invoke" it as many times as specified -- it isjust possilbe to call once and "cache" the result...
What do you think?



신고
tags : HotSpot, java
Trackback 0 : Comment 0

Write a comment


Java에서의 Out Of Memory Error(OOME)에 대한 나름대로의 정리...

Enterprise Java 2007.10.03 23:03

사내에서 하는 프로젝트의 일환으로 Java의 성능 이슈에 대한 다양한 컨텐츠를 작성 중인데... 그 중 유용하다고 생각되는 내용 일부를 블로그를 통해서 공개할 생각이다. 그 첫번째 내용으로 악명높은 Out Of Memory Error, 흔히 OOM(E)라고 부르는 현상의 원인과 해결책에 대해 정리한 문서를 소개한다...


OOME 개요

JVM이 일정한 크기의 메모리를 할당하는데 실패하면 Out Of Memory Error, 이른바 OOME가 발생한다.

OOME의 발생 원인은 매우 다양하며, 이는 JVM이 사용하는 메모리 공간의 다양성에 기인한다. 대부분의 JVM은그 사용 용도에 따라 메모리를 몇가지 종류로 구분해서 사용한다. 가령 Sun HotSpot JVM은 다음과 같은 세 가지 종류의메모리 공간을 사용한다.((참고) 통상적으로 Permanent Space는 Java Heap의 하위 영역으로 설명된다. 하지만 본 문서에서는 Java Heap = Young Generation + Old Generation으로 간주한다)

  1. Java Heap: 사용자가 생성하는 Java Object들이 거주하는 공간이다. -Xms와 -Xmx Option에 의해 크기가 결정된다.
  2. Permanent Space: Class에 대한 메타 정보를 저장하는 공간이다. -XX:PermSize=와 -XX:MaxPermSize= Option에 의해 크기가 결정된다.
  3. Native Heap: Java Object가 아닌 Native Object들이 거주하는 공간이다. Native Heap의 크기는 JVM Option으로 지정할 수 없으며, OS 차원에서 결정된다.


각 메모리 공간의 용도와 사용 방식이 틀리기 때문에 OOME또한 매우 다양한 상황에서 발생하게 된다. OOME가 발생하는 정확한 원인을 분석하려면 각 메모리 공간의 특성을 이해하고 그에 맞는 해결책을 모색해야 한다.

(주의) 비록 Java 언어와 JVM이 자동화된 메모리 관리 기능을 제공하지만, 이것이개발자나 관리자가 메모리 관리에 대해 무신경해도 된다는 것을 의미하지 않는다는 사실을 명심하자. Java에서도 잘못된 메모리관리는 여전히 많은 문제를 일으키며, Garbage Collection에 의한 성능저하나 OOME에 의한 Applictaion정지나 System Crash등이 대표적인 예이다.

Java Heap에서의 OOME

Java Heap에서 OOME가 발생하는 경우에는 다음과 같은 에러 메시지가 출력된다.

Exception in thread "main": java.lang.OutOfMemoryError: Java heap space 또는
Exception in thread main: java.lang.OutOfMemoryError: Requested array size exceeds VM limit

전자의 메시지는 Java Heap Space의 부족으로 Object를 생성하지 못하는 경우에 발생한다. 후자의메시지는 Java Heap의 최대 크기보다 큰 Array가 요청되는 경우에 발생한다. 가령 Java Heap의 최대 크기가256M인 상황에서 300M 크기의 Array를 생성하는 경우가 이에 해당한다.

Java Heap에서 OOME가 발생하는 이유는 다음과 같다.

  • Java Heap의 크기가 작은 경우
  • Memory Leak이 발생하는 경우
    • Application Logic에 의한 Memory Leak
    • JDK Bug나 WAS Bug에 의한 Memory Leak
  • finalize 메소드에 의한 Collection 지연


Java Heap의 크기와 OOME

Java Heap의 최대 크기가 Application의 메모리 요구량에 비해 작게 설정된 경우에 OOME가 발생한다.Memory Leak이 발생하지 않는데도 OOME가 발생한다면 Java Heap의 크기가 부족하다고 판단할 수 있다.-Xmx 옵션을 이용해서 Java Heap의 최대 크기를 키워주어야 한다.

Memory Leak과 OOME

Memory Leak이발생하는 경우에는 Java Heap의 크기와 무관하게 OOME가 발생할 수 있다. 아무리 Java Heap의 크기를 크게하더라도 결국 Memory Leak에 의해 Collection되지 않는 Garbage 객체들이 메모리를 다 소진하기 때문이다.Memory Leak은 대부분 잘못된 Application 로직에 의해 발생한다. Object에 대한 참조(Reference)관계가 복잡한 경우 조그마한 실수로 인해 사용되지 않은 Object를 계속해서 참조하게 된다. 이러한 Object들은 비록Application에서는 사용되지 않지만 Garbage Collection에 의해 메모리 해제가 이루어지지 않기 때문에OOME를 유발하게 된다.

JDK Bug나 WAS Bug에 의해서도 Memory Leak이 발생할 수 있다. JDK가 제공하는 라이브러리나WAS가 제공하는 라이브러리에서 로직 오류로 인한 Memory Leak 가능성이 있기 때문이다. ApplicationLogic에서 Memory Leak이 검출되지 않는 경우에는 JDK나 WAS의 Bug를 의심해볼 필요가 있으며 각 Vendor가제공하는 Bug Database를 통해 검색 가능하다.

finalize 메소드에 의한 Collection 지연과 OOME

특정 Class에 finalize 메소드가 정의되어 있는 경우, 이 Class Type의 Object는 GarbageCollection 발생시 즉각적으로 Collection 되지 않는다. 대신 Finalization Queue에 들어간 후Finalizer에 의해 정리가 된다. Finalizer는 Object의 finalize 메소드를 실행한 후 메모리 정리 작업을수행한다. 만일 finalize 메소드를 수행하는데 오랜 시간이 걸린다면 그 만큼 객체가 오랫동안 메모리를 점유하게 된다. 이로인해 OOME가 발생할 확률이 높아진다. 이런 이유 때문에 finalize 메소드는 되도록 사용하지 말아야 한다.

Object Allocation Profiling

Java Heap의 메모리 부족 문제를 정확하게 분석하려면 Object Allocation Profiling을 수행해야한다. 즉, 어떤 Object가 어느 개수만큼 생성되었으며 얼마나 많은 메모리를 차지하는지 분석할 필요가 있다. HProf는 모든 JVM이 표준으로 제공하는 Profiler로, 간단한 Object Allocation Profiling 기능을 제공한다.

 java -Xrunhprof:heap=sites [Main Class] 

또는 다음과 같이 doe(dump on exit) Option을 비활성화해서 시간순으로 Profiling을 수행할 수도 있다.

 java -Xrunhprof:heap=sites,doe=n [Main Class]
...
Control+Break (혹은 다른 Console에서 kill -3 [pid])

Java Process에서 Signal을 보내서 Dump를 생성하는 방법은 Thread Dump를 참조한다.

아래에 HProf를 이용한 Object Allocation Profiling 결과의 간단한 Sample이 있다. 아래 Sample에서는 byte[] 유형의 객체가 20%의 Heap 공간을 사용하는 것을 알 수 있다.

        percent          live          alloc'ed  stack class
rank self accum bytes objs bytes objs trace name
1 20.36% 20.36% 190060 16 190060 16 300000 byte[]
2 14.92% 35.28% 139260 1059 139260 1059 300000 char[]
3 5.27% 40.56% 49192 15 49192 15 300055 byte[]
4 5.26% 45.82% 49112 14 49112 14 300066 byte[]
5 4.32% 50.14% 40308 1226 40308 1226 300000 java.lang.String
6 1.62% 51.75% 15092 438 15092 438 300000 java.util.HashMap$Entry
7 0.79% 52.55% 7392 14 7392 14 300065 byte[]
8 0.47% 53.01% 4360 16 4360 16 300016 char[]
9 0.47% 53.48% 4352 34 4352 34 300032 char[]
10 0.43% 53.90% 3968 32 3968 32 300028 char[]
11 0.40% 54.30% 3716 8 3716 8 300000 java.util.HashMap$Entry[]
12 0.40% 54.70% 3708 11 3708 11 300000 int[]

Permanent Space에서의 OOME

Permanent Space에서 OOME가 발생하면 다음과 같은 에러 메시지가 출력된다

Exception in thread "main": java.lang.OutOfMemoryError: Perm Gen space'

Permanent Space는 Class의 메타 정보를 저장하는 공간이다. 따라서 많은 수의 Class를 로딩하는Application의 경우 Permanent Space의 크기가 작으면 OOME가 발생할 수 있다. 다음과 같은 유형의Application들에서는 Permanent Space의 크기를 키워줄 필요가 있다.

  • 매우 많은 수의 JSP 파일을 로딩하는 Web Application. JSP 파일은 Servlet으로 변환된다.하나의 Servlet은 하나의 Java Class에 해당한다. 따라서 이 경우 매우 많은 수의 Class가 로딩된다.
  • ReflectionMechanism을 사용해 동적으로 Class를 로딩하는 Framework. Spring과 같은 현대적인 Framework들은Reflection Meachanism을 통해 동적으로 Class를 생성한다. 이 경우 개발자가 의도하지 않은 많은 수의Class들이 로딩될 수 있다.

이런 문제는 대부분의 Permanent Space의 크기를 키워주면 해결된다.-XX:PermSize=, -XX:MaxPermSize= Option을 이용해Permanent Space의 최소 크기와 최대 크기를 지정할 수 있다.

Class Loading 모니터링

Permanent Space에 Loading되는 Class의 목록을 모니터링함으로써 OOME가 발생하는 원인을 간접적으로 분석할 수 있다. 다음과 같은 방법을 통해 Class Loading을 모니터링할 수 있다.

  • -verbose:gc: Loading되는 Class들을 Standard Out을 통해 출력해준다.
  • Platform MBean: JMX 표준을 통해 제공되는 ClassLoadingMXBean API를 이용하면 프로그래밍적으로 Class Loading 정보를 얻을 수 있다.
  • JConsole: JConsole을 이용하면 Class Loading 정보를 조회할 수 있다. JConsole은 JMX 클라이언트의 표준 샘플로 Platform MBean과 통신해서 Class Loading 정보를 얻는다.

아래에 -verbose:class 옵션에 의한 Class Loading 모니터링의 간단한 Sample이 있다. Open된 jar 파일과 Loading된 Class 목록을 확인할 수 있다.

[Opened c:bea10jdk150_06jrelibrt.jar]
[Opened c:bea10jdk150_06jrelibjsse.jar]
[Opened c:bea10jdk150_06jrelibjce.jar]
[Opened c:bea10jdk150_06jrelibcharsets.jar]
[Loaded java.lang.Object from c:bea10jdk150_06jrelibrt.jar]
[Loaded java.io.Serializable from c:bea10jdk150_06jrelibrt.jar]
[Loaded java.lang.Comparable from c:bea10jdk150_06jrelibrt.jar]
[Loaded java.lang.CharSequence from c:bea10jdk150_06jrelibrt.jar]
[Loaded java.lang.String from c:bea10jdk150_06jrelibrt.jar]
[Loaded java.lang.reflect.GenericDeclaration from c:bea10jdk150_06jrelibrt.jar]
...

(참조) IBM JVM에서는 Thread Dump에서도 Class Loading 정보를 제공한다.

Class Reloading과 OOME

현대적인 대부분의 WAS가 Class Reloading 기능을 제공한다. Class Reloading이란 Runtime에Class가 재생성되면 이를 JVM을 Reboot하지 않고 Reloading하는 기능을 의미한다. 일부 WAS의 경우Class가 Reloading될 때 이전 버전의 Class를 해제하지 않는 경우가 있다. 따라서 Class Reloading이자주 발생하면 Permanent Space가 금방 꽉차게 되고 OOME가 발생하게 된다. 이와 같은 경우에는 WAS가 제공하는버그 패치를 적용하거나 WAS를 주기적으로 Restart해야 한다.

Native Heap에서의 OOME

Java Heap과 Permanent Space가 Java와 관련된 Object들이 거주하는 공간인 반면, NativeHeap은 OS 레벨의 Native Object나 JNI Library 레벨의 Native Object이 거주하는 공간이다.

Native Heap에서 OOME가 발생하면 다음과 같은 에러 메시지가 출력된다.

java.lang.OutOfMemoryError: request bytes for . Out of swap space? 또는
java.lang.OutOfMemoryError: (Native method)' 또는
java.lang.OutOfMemoryError: unable to create new native thread


첫번째 메시지는 VM code 레벨에서 메모리 부족 현상이 발견된 경우이다. 두번째 메시지는 JNI나 Native Method에서 메모리 부족 현상이 발견된 경우에 해당한다. 세번째 메시지는 Thread를 생성할 수 없을 때 발생한다. Thread는Native Heap 공간의 메모리를 필요로 하기 때문에 Native Heap 공간의 메모리가 부족하면 Thread 생성시OOME가 발생한다.

Native Heap에서 메모리 부족이 발생하는 이유는 매우 다양하다.

  • Thread Stack Space가 부족한 경우
  • Virtual Space Address가 소진된 경우
  • Swap Space가 모자란 경우
  • JNI Library에서 Memory Leak이 발생하는 경우

Thread Stack Space와 OOME

Java Thread는 Native Heap 공간에 Stack Trace를 저장할 공간을 필요로 한다. ThreadStack Space의 크기는 -Xss 옵션을 통해 지정된다. -Xss 옵션을 통해지정되는 공간은 개별 Thread가 사용하는 공간이다. 만일 N개의 Thread가 활성화되면 N* 만큼의메모리 공간이 필요하다.

대부분의 OS에서 Thread Stack Size는 512K ~ 1M 사이다. 따라서 많은 수의 Thread가 활성화되면 Thread Stack Space만으로도 큰 크기의 Native Heap 메모리 공간을 소모한다.

Thread Stack Space 문제에 의한 OOME를 해소하는 방법은 다음과 같다.

  • Thread의 수를 줄인다. 동시에 수십개 이상의 Thread를 사용하는 것은 메모리의 문제 뿐만 아니라 지나친 Context Switching으로 인해 성능을 저하시키는 요인이 된다. Thread Pool 기법을 사용해서 동시 Thread의 수를 줄인다. 대부분의 WAS들이 Thread Pool 기법을 사용하고 있다.
  • Thread Stack Size를 줄인다. 대부분의 OS에서 Thread Stack Size는512K ~ 1M이다. 만일 많은 수의 Thread가 필요한 Application이라면 Thread Stack Size를줄임으로써 OOME를 방지할 수 있다. 많은 경우 -Xss128k 정도나 -Xss256k 정도의 크기에서도 문제없이 작동한다.단, Stack Size가 줄어든 만큼 Stack Overflow Error가 발생할 확률은 높아진다.
  • Java Heap 크기를 줄인다. 32bit Process가 사용 가능한 메모리 공간은 OS에따라 2G ~ 4G로 제한된다. 하나의 Java Process가 사용 가능한 공간은 [Java Heap+PermanentSpace+Native Heap]으로 이루어진다. 따라서 Java Heap이 지나치게 큰 공간을 사용하는 경우 NativeHeap에서 사용 가능한 공간이 줄어들게 된다. 따라서 Java Heap 크기를 줄이면 Native Heap의 메모리 부족에의한 OOME 문제를 해결 할 수 있다. 하지마 Java Heap 크기를 지나치게 줄이면 Java Heap 부족에 의한 OOME현상이 발생할 수 있으므로 유의해야 한다. Java Heap 크기를 줄이는 방법은 Thread Stack Space의 부족 문제뿐 아니라 Native Heap 부족에 의한 OOME 문제를 줄이는 공통적인 해결 방법이다.
  • 64bit JVM을 사용한다. 64bit JVM에서는 32bit JVM Process가 가지는2G ~ 4G의 제한이 없다. 따라서 Native Heap의 메모리 부족 문제가 줄어든다. 이 방법 또한 Native heap부족에 의한 OOME 문제를 줄이는 공통적인 해결 방안이다.

64bit JVM을 사용하는 경우, 다음과 같은 사실에 유의해야 한다.

  1. 일반적으로 32bit Application의 성능이 64bit Application에 비해 더 나은 성능을보이는 경우가 많다. 따라서 64bit JVM을 사용하는 경우 약간의 성능 저하가 발생할 수 있다는 사실에 유의해야 한다.
  2. 과도한 Virutal Memory의 사용은 Application의 성능을 저하시키는 주요인이다. JavaApplication의 성능은 모든 Object들이 Physical Memory에 머물러 있을때 가장 뛰어나다. 만일Physical Memory를 초과하는 크기의 Virtual Memory를 사용하면 Physical Memory의 일부를Disk에 저장하는 Paging In/Out이 발생한다. Paging In/Out은 Memory Operation에 비해 매우느리며 그만큼 Application의 성능도 저하된다.


Virtual Address Space와 OOME

32bit JVM에서 사용가능한 Virtual Address Space의 최대 크기는 OS에 따라 2G ~ 4G로제한된다. Java Process의 경우 Java Heap과 Permanent Space를 제외한 나머지 공간만을 NativeHeap이 사용할 수 있다. 가령 2G의 Virtual Address Space만이 사용가능하다고 가정하자. 이 때 JavaHeap이 1G, Permanent Space가 200M를 사용한다면 Native Heap이 사용 가능한 최대 크기는 800M에불과하다. 800M 중에는 OS가 Process 관리를 위해 사용하는 기본 메모리가 포함되기 때문에 실제로 JavaApplication이 사용 가능한 Native Heap의 크기는 훨씬 줄어든다. 따라서 이 경우 Native Heap 공간부족에 의한 OOME가 발생할 확률이 높아진다.

Virtual Address Space 부족에 의한 OOME를 해결하는 방법은 Thread Stack Space에의한 OOME 해결방안과 일맥상통한다. Java Heap 크기를 줄이거나 64bit JVM를 사용한다. Thread 수를줄이거나 Thread Stack Size를 줄임으로써 Native Heap 공간을 확보하는 것도 방법이 될 수 있다.

Swap Sapce와 OOME

Physical Memory를 초과하는 Virtual Memory 요청이 발생하면 Paging In/Out을 통해 필요한 메모리를 확보한다. Paging In/Out을 위한 공간이 Swap 공간이다. 따라서 Swap Space가 부족하면 Paging In/Out에 실패하고 이로 인해 OOME가 발생한다.

여러 개의 Process가 Swap Space를 사용하는 경우 Swap Space 부족에 의한 OOME가 발생할확률이 높아진다. OS가 제공하는 툴들을 통해 Swap Space와 Paging In/Out을 모니터링해야 하며, SwapSpace가 부족한 경우에는 크기를 키워주어야 한다.

OOME와 Fatal Error Log

Native Heap에서 OOME가 발생하면 JVM은 심각한 상황이라고 판단하고 Fatal Error Log를 남긴다. 아래에 OOME가 발생한 상황에서의 Fatal Error Log의 Header 정보에 대한 간단한 Sample이 있다.

#
# An unexpected error has been detected by Java Runtime Environment:
#
# java.lang.OutOfMemoryError: requested 20971520 bytes for GrET in C:BUILD_AREA
jdk6_02hotspotsrcsharevmutilitiesgrowableArray.cpp. Out of swap space?
#
# Internal Error (414C4C4F434154494F4E0E494E4C494E450E4850500017), pid=5840, ti
d=5540
#
# Java VM: Java HotSpot(TM) Client VM (1.6.0_02-b06 mixed mode)
# An error report file with more information is saved as hs_err_pid5840.log
#
# If you would like to submit a bug report, please visit:
# http://java.sun.com/webapps/bugreport/crash.jsp
#

Fatal Error Log를 통해 OOME를 유발한 Thread와 Stack Trace를 추적할 수 있다. 이 정보가 곧 해결책을 의미하지는 않지만, 추가적인 분석을 위한 힌트가 될 수 있다.

신고
Trackback 0 : Comments 5
  1. 햇병아리프로그래머 2009.05.04 09:52 신고 Modify/Delete Reply

    좋은 글이네요 ~~ 많은 도움이 되었습니다. ^^

  2. 방문객 2010.04.13 20:51 신고 Modify/Delete Reply

    좋은 정보 담아 갑니다... 출처는 상단에 밝혀두겠습니다.

  3. 방문객 2010.05.25 10:11 신고 Modify/Delete Reply

    좋은 글 읽고 갑니다. 유용한 정보 감사합니다.

  4. raintree 2012.10.02 11:20 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

  5. 샤푸한늑대 2012.11.22 16:18 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment


Sun Java Forum - 잘못된 Young Generation 크기에 의한 Full GC 발생

Enterprise Java 2007.09.22 22:24
아래 논의 내용은 잘못된 New Generation 크기에 의한 Full GC 발생에 관한 것이다.

"-Xmn64m -Xmx64m"의 옵션을 사용했는데 왜 Full GC만 발생하느냐는 것이 질문의 요지이다.
-Xmn은 New Generation의 크기를, -Xmx은 Heap(New+Tenured) Size의 최대 크기를 지정하는 것이므로 New Generation의 크기를 Heap 크기와 동일하게 준 것이다.

아래에 첨부된 GC log를 보면 알 수 있듯이 이 경우 JVM은 Tenured Space를 0이 아닌 2M 정도로 지정하고 있다. 이것이 Max Heap Size가 64M인 경우 Tenured Space의 최소 크기인 것을 알 수 있다.

이 경우 Full GC만 계속해서 발생하는 이유는 Promotion Failure 때문이다. Young Generation을 정리하는 Minor GC과정에서 Live Object들을 Tenured Space로 승격(Promotion) 시키는 현상이 발생하는데 만일 Tenured Space에 충분한 여유 공간이 없으면 JVM은 Full GC를 수행해서 모든 Garbage들을 다 제거하기 위해 노력한다. 즉 Promotion Failure가 발생한 경우에는 반드시 Full GC가 수반된다.

이런 이유 때문에 New Generation의 크기를 지나치게 크게 설정하는 것은 매우 위험하다. New Generation의 크기를 얼마 정도로 해야 하는지는 정답이 없지만 절대 전체 Heap Size의 절반을 넘어서는 안된다.

내가 생각하는 가장 좋은 방법은 시스템 기본값으로 그대로 둔 상태에서 Full GC의 발생 정도를 보고 증감을 시키는 것이다. Full GC가 빈번하게 발생하는 경우에는 값을 감소시키고, 반대의 경우에는 값을 증가시키면서 최적의 값을 찾는다.

Sun HotSpot JVM은 New Generation의 크기를 동적으로 변경하는 기능을 가지고 있다. -XX:+UseAdaptiveSizePolicy 옵션에 의해 제어되며 기본값은 True이다. 하지만 간혹 버그나 오동작에 의해 이 동적인 New Generation 크기 변경이 문제를 일으키는 경우가 있다. 만일 메모리의 여유가 충분한데도 Full GC가 발생한다면 이러한 현상을 의심해보아야 하며 -XX:-UseAdaptiveSizePolicy 옵션을 이용해서 동적인 크기 조정을 비활성화시켜볼 필요가 있다.



0 Duke Stars available
This topic has 1 reply on 1 page.
whartung
Posts:131
Registered: 2/15/00
All my JVM does is full GC's
Sep 21, 2007 4:20 PM

I have a simple application, it doesn't use much memory.

In the beginning, as the heap expands, I get my incremental GCs.

But eventually, I get Full GCs, and after that all I get is full GCs. No matter how much memory I give my app.

My app doesn't require a lot of memory. After GC it rarely goes above 8M.

I've run it with everything from -Xmx16m up to -Xmx64m.

When I PrintGCDetails, or look at it through jconsole, the tenured generation is always full.

$ java -version
java version "1.5.0_11"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_11-b03)
Java HotSpot(TM) Client VM (build 1.5.0_11-b03, mixed mode)

java -Xmn16m -Xmx16m -verbose:gc -XX:+PrintGCDetails

[Full GC [Tenured: 2047K->2047K(2048K), 0.1542593 secs]16831K->5629K(16832K), [Perm : 24339K->24339K(24576K)], 0.1543772secs]

If I run with 64M, it just takes longer before the Full GC, but I neverget the incrementals again, and the Tenured space is still 2MB.

java -Xmn16m -Xmx16m -verbose:gc -XX:+PrintGCDetails

[Full GC [Tenured: 2047K->2047K(2048K), 0.2037613 secs] 61055K->7943K(61056K), [Perm : 27706K->27
706K(27904K)], 0.2038618 secs]

I'm assuming I'm getting the Full GCs because the Tenured generation isfull. But I can't seem to find a way to change the size. I triedNewRatio, but it didn't seem to have any affect at all.

This isn't really a performance issue, but it is a pedantic issue as Idon't think I should be doing Full GCs all of the time, that just seemslike an "unhealthy" or at least "out of balance" JVM/Applicationconfiguration, so I'd like to get the GC working better in a healthierway with more incremental GCs rather than always doing Full GCs.

Any hints would be appreciated.

Dion_Cho
Posts:25
Registered: 9/6/07
Re: All my JVM does is full GC's
Sep 22, 2007 3:11 AM (reply 1 of 1)

Why Xmn == Xmx? (Maybe just for experimental test....)

As gc log says, your tenrued size is always only < 2M size. Why?because you set new generatio size == max heap size. JVM set thetenured size to its minimum.

Tenured size is so small that your young objects located in new spacecannot be promoted to tenured space. So JVM decides to start full gc -to clear all the garbages.

For this reason, it is unresonable and meaningless to set younggeneration size > tenured generation size. It might cause full gccontinuously.
Additionaly, keep in mind that too big young generation sometimes has tendency to make problems related to full gc.



신고
Trackback 0 : Comment 0

Write a comment


한국은 왜 Software의 변두리에만 머물러 있을까...

Enterprise Java 2007.09.19 22:38
요즘 공부삼아 Sun Java Forum(http://forum.sun.java.com)에 들르곤 한다. 그리고 아는 내용이 나오면 답변도 달기도 한다.
(물론 영어로... ^^)

Java나 Oracle Forum 사이트들을 볼 때 마다, 그리고 Google에서 기술적인 내용을 검색할 때마다 자괴감에 빠지곤 한다.
대한민국의 엔지니어들은 언제쯤 저 영어의 바다에 떠 있는 Software의 주류에 들어갈 수 있을까?
아니, 언제쯤 그들만의 리그가 아닌 대한민국의 리그를 만들 수 있을까?

내 주위나 온라인 상에서 가끔 출중한 실력을 갖춘 엔지니어들을 볼 때가 있다.
하지만 어느 누구도 태생의 한계에서 벗어나지 못한다.
아무리 실력이 좋아도 대한민국이라는 좁은 세계에 갇혀 지낼 수 밖에 없는 운명이다.

안타깝게도 이게 현실이다.

대한민국의 이 많은 엔지니어들이 영어로 자신의 생각을 표현하고, 질문하고 대답할 수 있다면
그 순간 대한민국 Software의 영역과 시장성이 글로벌한 수준으로 올라간다.

그래서 나는 어떤 개인적인 이익을 위해서라기 보다는
대한민국 Software 업계의 수준을 전세계에 알리는 서곡을 울린다는 마음으로
가끔 영어로 글을 적기도 하고, 미국놈이나 인도놈, 유럽놈들이 설쳐대는 온라인 세계에서
가끔 어줍짢은 영어를 주고 받기도 한다.

그런 차원에서 앞으로 이 블로그에 내가 참가한 Forum(의 Article을 가끔 올릴까 한다.
언젠가 대한민국의 똘똘한 엔지니어들이 온라인 세계에서 미국놈들한테 한 수 가르치고 있을 날을 기대해보면서...

=====================================================================================
아래 내용은 http://forum.sun.java.com 에서 올라온 질문에 대해 토의 내용이다.
Dion_Cho 라는 닉네임으로 활동중... ^^;
진짜배기 코쟁이 고수들에 비해 초라한 영어와 지식을 구사하고 있다. ^^;


etolson@hcmny.com
Posts:14
Registered: 4/18/05
Exorbitant Garbage Collection Times
Aug 17, 2007 9:10 AM

Once a day, at around 4-4:30am, our application experiences a singleFull GC with taking an exorbitant amount of time. A Full GC kicks inand pauses all threads for 5 to 30 minutes. Full GC's regularly occurat other times and complete in 5-20 seconds. Anyone seen this or anyhave any ideas about this?

Example of normal GC that occurs frequently throughout the day:

[Full GC[Unloading class $Proxy136]
....
4632722K->1616289K(6141952K), 14.9400110 secs]

Example of ridiculously long GC that occurs daily at 4-4:30am:
[Full GC[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor455]
....
5456231K->2017269K(6141952K), 492.0402160 secs]

Here's our VM params:
-server -XX:-OmitStackTraceInFastThrow -Xincgc -XX:+CMSIncrementalMode-XX:+CMSIncrementalPacing -XX:MaxGCPauseMillis=20000-XX:+DisableExplicitGC -XX:NewSize=1500m -XX:SurvivorRatio=18-verbose:gc
-Xms6000M -Xmx6000M

We're running Java 1.6 on Linux, Redhat 3.
etolson@hcmny.com
Posts:14
Registered: 4/18/05
Re: Exorbitant Garbage Collection Times
Aug 17, 2007 9:29 AM (reply 1 of 5)

By the way I should point out that this is a very powerful Linux serverand is hosting only this application. During the long Full GC, the loadon the server is relatively low.
PeterKessler
Posts:77
Registered: 10/2/06
Re: Exorbitant Garbage Collection Times
Aug 17, 2007 5:13 PM (reply 2 of 5)

If you post the output of running with -XX:+PrintGCTimeStamps -XX:+PrintGCDetails (and without-verbose:gc, please) we can give more advice. If the logs are too longto post, you can email them HotSpotGC-Feedback (at) Sun.COM. Pleaseinclude your full command line (e.g., the one you show omits at least"-d64").

From the little you've shown, it sounds like most of the time CMS cankeep up with your rate of garbage generation, but something happensaround 4AM that causes it to "lose the race" and bail out to a fullmark-compact collection. That's a single-threaded stop-the-worldcollector, and won't meet your pause time goals. The logs would say.

The other possibility is that your Java application is idle around 4AM,but something else is running on the machine and forces the 6GB of yourheap out to disk. then the next collection will have to page all thatback in. That might account for 10 (or even 30) minutes for acollection. Or it could be a combination: CMS might start a concurrentcollection, but paging might cause it to take so long that it bails outto the stop-the-world collector. That might be harder to see from thelogs, but we are pretty good at reading logs.
etolson@hcmny.com
Posts:14
Registered: 4/18/05
Re: Exorbitant Garbage Collection Times
Aug 21, 2007 6:51 PM (reply 3 of 5)

Thanks very much for your suggestions. Unfortunately it seems like neither applies for these reasons:

1. This is an extremely low-activity period of time for thisapplication, as it's a trading application used primarily for USmarkets and secondarily for Asian markets, and this time is outside USand almost all Asian markets.

2. There should be absolutely nothing else running on this machine, asit's dedicated to this application. The having been paged out doesdefinitely seem to be the most likely explanation, but I just don'tunderstand why it was paged out...

I'll get you the logs as requested this week.
etolson@hcmny.com
Posts:14
Registered: 4/18/05
Re: Exorbitant Garbage Collection Times
Sep 13, 2007 7:34 AM (reply 4 of 5)

Just experienced a 498 second (yikes!) garbage collection pause. Theentry from the log is below (we added -XX:+PrintGCTimeStamps-XX:+PrintGCDetails and removed -verbose:gc). I will also send theentire log to the email address you have provided.

Note that we actually reduced our Xmx to 4000M (from 6000M) despitethis machine having 8gig physical ram in the hopes that this wouldprevent any paging, and it seems to have drastically improved thesituation - these exorbitant pauses now occur only very seldomly.

This is the full command we're justing to start the JBoss JVM:

/proj/bo/apps/jdk/production/bin/java -Dprogram.name=run.sh -server -XX:-OmitSta
ckTraceInFastThrow -Xincgc -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:MaxGCPauseMillis=20000 -XX:+DisableExplicitGC
-XX:NewSize=1500m -XX:SurvivorRatio=18 -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Djava.endorsed.dirs=/var/local/jboss/jboss-c
urrent/lib/endorsed -Dsystem.state=production -Dcom.hb.common.api.util.Environment.app.name=Hermes -Djboss.partition.name=as20.
nyc.hcmny.com -Dorg.jboss.security.SecurityAssociation.ThreadLocal=true -Doracle.net.tns_admin=/var/opt/oracle/etc -Djnp.discov
eryPort=1103 -classpath /var/local/jboss/jboss-current/bin/run.jar:/proj/bo/apps/jdk/production/lib/tools.jar -Xms4000M -Xmx400
0M -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=8134 -Dcom.sun.management.jmxremote.authenticate=true -Dc
om.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.password.file=/proj/bo/jmxremote.password org.jboss.Main -
cdefault

This is the exact JRE we're using:
java version "1.6.0"
Java(TM) SE Runtime Environment (build 1.6.0-b105)
Java HotSpot(TM) 64-Bit Server VM (build 1.6.0-b105, mixed mode)

Here's the 498 second GC pause:
103999.802: [GC 103999.802: [ParNew (promotion failed):1459200K->1459200K(1459200K), 478.7897900 secs]104478.592:[CMS104483.552: [CMS-concurrent-mark: 5.170/491.280 secs]
(concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor605]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor866]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor870]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor887]
[Unloading class sun.reflect.GeneratedMethodAccessor267]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor864]
[Unloading class sun.reflect.GeneratedConstructorAccessor148]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor861]
[Unloading class sun.reflect.GeneratedMethodAccessor268]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor606]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor862]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor886]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor706]
[Unloading class sun.reflect.GeneratedConstructorAccessor145]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor865]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor350]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor860]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor868]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor863]
[Unloading class sun.reflect.GeneratedConstructorAccessor147]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor867]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor869]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor185]
[Unloading class sun.reflect.GeneratedConstructorAccessor125]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor871]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor707]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor708]
: 2517456K->2073715K(2560000K), 19.7399910 secs] 3927185K->2073715K(4019200K) icms_dc=5 , 498.5297810 secs]
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.ObjectOutputStream$BlockDataOutputStream.drain(ObjectOutputStream.java:1838)
at java.io.ObjectOutputStream$BlockDataOutputStream.setBlockDataMode(ObjectOutputStream.java:1747)
at java.io.ObjectOutputStream.(ObjectOutputStream.java:226)
21:37:07,931 WARN [TransactionImpl] TransactionTransactionImpl:XidImpl[FormatId=257,GlobalId=as20.nyc.hcmny.com/163214, BranchQual=, localId=163214] timedout. status=STATUS_ACTIVE
2007-09-12 21:37:08
Dion_Cho
Posts:15
Registered: 9/6/07
Re: Exorbitant Garbage Collection Times
Sep 13, 2007 6:38 PM (reply 5 of 5)

Exact answer will be given by Sun. :)

Your exorbitant full gc time seems to be caused by promotion failure as the log says.

My suggestion is

1) New generation seems big. Especially under CMS. It might causepromotion failure. Decrease new generation size. 500M ~ 1G seems to befine(And optionally decrease -XX:SurvivorRatio to 8)

2) Try -XX:CMSInitiatingOccupancyFraction=55 or 50. Lower value willnot harm, only with negligible side effect. It will initate concurrentcollection more agressively to reduce promotion failure. Optionallyapply -XX:+UseCMSInitiatingOccupancyOnly option.

There are lots of discussions and answers in this forum about theperformance of CMS collector. Some search will you give great hints.
This topic has 5 replies on 1 page.

신고
Trackback 0 : Comments 3
  1. 강한구 2009.12.23 12:12 신고 Modify/Delete Reply

    1년전 대학교때 영어안하고 개발만해서 성공해야지라고 마음먹었던제가
    지금이되서야 '아.....영어는 선택이 아니라 필수구나.....'라는 마음을 가졌습니다.

    1년동안 어떤분야로 나갈지 고민하다가 DB만드는쪽으로 결정해서 공부하다가
    오게되었습니다. 좋은정보가 많이 있네요 : ) 감사합니다. 항상 건강하시고 2009년 마무리 잘하세요~~ : )

  2. 지우 2011.11.07 09:44 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

  3. moncler online 2013.01.05 16:35 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment


JMP - 공짜치곤 괜찮은 Java Profiler

Enterprise Java 2007.09.18 17:57
Java Application에서 발생하는 성능 문제를 다루다 보면 반드시 Profiler류의 툴을 사용해야 할 때가 있다. Profiler들은 다음과 같은 기본적인 기능들을 통해 Application 내부에서 발생하는 일을 좀 더 수치적인 관점에서 보게 해준다.
  • Object 생성 수치와 메모리 사용률
  • Method 호출 회수와 구동 시간
  • Garbage Collection 작동과 Heap 사용률
  • 기타 등등...
이러한 정보들은 대부분 Java API를 통해 제공되지 않으며 별도의 C/C++ Interface를 통해 제공된다. JDK 1.4까지는 JVMPI(JVM Profiler Interface)라는 이름으로 제공되었다. JDK 1.5부터는 흩어져 있던 API들을 교통 정리하고 통합해서 JVMTI(JVM Tool Interface)라는 이름으로 제공된다.

결국 Java Application을 Profiling할 수 있으려면 C/C++로 작성된 별도의 Agent가 필요한 셈이다.

다행히 Sun이 JVMPI/JVMTI를 만들면서 API의 검증 차원에서 간단한 Profiler를 만들어서 제공한다. 이것이 흔히들 사용하는 hprof(Heap and CPU Profiling Agent)이다. 다음과 같이 실행해보면 hprof가 제공하는 기능을 알 수 있다.(hprof는 어떤 종류의 JVM을 막론하고 공통적으로 제공되는 툴이다)

Prompt> java -Xrunhprof:help

HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)

hprof usage: java -agentlib:hprof=[help]|[

Option Name and Value Description Default
--------------------- ----------- -------
heap=dump|sites|all heap profiling all
cpu=samples|times|old CPU usage off
monitor=y|n monitor contention n
format=a|b text(txt) or binary output a
file= write data to file java.hprof[.txt]
net=: send data over a socket off
depth= stack trace depth 4
interval= sample interval in ms 10
cutoff= output cutoff point 0.0001
lineno=y|n line number in traces? y
thread=y|n thread in traces? n
doe=y|n dump on exit? y
msa=y|n Solaris micro state accounting n
force=y|n force output to y
verbose=y|n print messages about dumps y

Obsolete Options
----------------
gc_okay=y|n

Examples
--------
- Get sample cpu information every 20 millisec, with a stack depth of 3:
java -agentlib:hprof=cpu=samples,interval=20,depth=3 classname
- Get heap usage information based on the allocation sites:
java -agentlib:hprof=heap=sites classname

Notes
-----
- The option format=b cannot be used with monitor=y.
- The option format=b cannot be used with cpu=old|times.
- Use of the -Xrunhprof interface can still be used, e.g.
java -Xrunhprof:[help]|[
will behave exactly the same as:
java -agentlib:hprof=[help]|[

Warnings
--------
- This is demonstration code for the JVMTI interface and use of BCI,
it is not an official product or formal part of the J2SE.
- The -Xrunhprof interface will be removed in a future release.
- The option format=b is considered experimental, this format may change
in a future release.

위의 Descprition을 보면 알겠지만, 데모용으로 만든 것치고는 상당히 다양한 기능을 제공한다. 잘 이용하면 굳이 상용 Profiler를 사용할 필요가 없을 정도로...

하지만, 역시 GUI를 제공하지 않는다는 것은 아쉬운 점이다. 또한 Call Tree나 Object 연관 분석 등 좀 더 디테일한 정보를 제공하지 않는다는 점도 치명적일 수 있다.

불행하게도, 멋진 GUI와 더 많은 스펙을 제공하는 상용 Java Profiler들은 가격이 만만치 않다. 물론 그 가격값을 할 때가 있겠지만...

Hprof를 능가하는 Profiler를 공짜로 사용하고자 하는 사람들이 많이 선택하는 툴이 바로 JMP이다. JMP는 Java Memory Profiler의 약자로 http://www.khelekore.org/jmp/에서 정보를 얻을 수 있다.

아래 그림은 JMP를 이용해 Object/Method/Thread/GC/Heap을 모니터링하는 화면 예제이다. UI는 촌스럽지만 꼭 필요한 정보를 제공하는데는 인색하지 않다.

Prompt> java -Xrunjmp:jvmhold -Xmx258m -cp . gc_dump 1200000




http://www.khelekore.org/jmp/ 에서 설치 및 사용법, 성능 이슈에 대한 풍부한 정보를 얻을 수 있다. Java Application의 성능 문제 때문에 고민하는 사람이라면 한번 쯤 JMP를 사용해 보는 것을 고려해보는 것도 나쁘지 않을 것이다.

PS) JMP와 같은 Profiler 류의 툴은 Application의 성능을 크게 떨어뜨린다. 이것은 JVMPI/JVMTI와 같은 Interface를 사용하는 한에서는 피할 수 없는 것이다. 이러한 사실을 염두에 두고 사용해야 할 것이다...


신고
Trackback 0 : Comment 0

Write a comment


[Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part4

Enterprise Java 2007.09.18 11:13
4. 큰 New Generation에 의한 Full GC 발생

다음과 같은 상황을 가정해보자
  • 전체 Heap의 크기는 1.5G이다.
  • New Generation의 크기를 전체 Heap의 1/4 정도로 크게 잡았다(일반적인 가이드)
  • 1G 정도에 육박하는 객체 정보를 메모리에 관리하고자 한다.

위와 같은 Java Application을 구동하면 그 결과는 어떻게 될까?

Full GC가 자주 발생할 확률이 매우 높다. Tenured Space가 큰 메모리 객체(1G)를 계속 보유하고 있기 때문에 New Generation에서 Promotion 되는 객체를 감당하지 못하게 되는데 이 경우 반드시 Full GC가 발생한다. 이런 현상을 Promotion Failure라고 부른다.

Promotion Failure는 Minor GC에서는 항상 발생할 가능성이 있다. Minor GC가 발생할 때 Live Object들은 Survior Space나 Tenured Space로 옮겨지게 되는데, 이 때 Tenured Space에 공간이 부족하면 Full GC가 발생하게 된다.

위의 상황을 다시 정리해보면 Tenured Space에 1G에 달하는 객체들이 상주하고 있다. 이런 상황에서 New Generation의 크기를 크게 하면 Promotion Failure가 발생할 확률이 매우 높아진다. 따라서 이런 경우에는 New Generation의 크기를 작게 주어야 한다.

New Generation 크기의 속성을 잘 이해할 필요가 있다. New Generation의 크기가 크면 Minor GC는 유리해지지만 Full GC에서는 불리해질 확률이 높다는 기본 원리를 염두에 두고 Application 속성에 따라 최적의 크기를 찾을 필요가 있다.

PS) 다행히 New Generation과 Survivor Space의 크기를 JVM에 의해 자동으로 관리된다. -XX:+UseAdaptiveSizePolicy 옵션에 의해 New Generation의 자동화된 크기 관리가 이루어지면 디폴트로 활성화되어 있다. 하지만 간혹 강제적으로 -XX:NewRatio 옵션을 이용해 크기를 설정해야만 문제가 해결되는 경우가 있다.

-------------------------------------------------------------------------------------
다음 글에 계속





신고
Trackback 0 : Comment 0

Write a comment


[Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part3

Enterprise Java 2007.09.13 17:51
3. Heap 여유 공간이 충분한데도 OOME(OutOfMemoryException)이 발생한다?

간혹 Heap의 여유 공간이 충분한데도 OutOfMemory Error가 나는 경우가 있다. 이러한 상황을 이해하려면 Java Application이 사용하는 메모리가 여러 영역으로 나뉜다는 사실을 이해해야 한다.

Java Application이 사용하는 메모리 영역은 보통 다음과 같이 분류된다.

- Permanent Space: Class 정보를 저장
- Java Heap: Object 정보를 저장
- Native Heap: JNI, Thread Stack, 기타 Native 정보를 저장

우리가 흔히 접하는 Memory 문제는 대부분 Java Heap에서 발생한다. Java Application이 할당하는 오브젝트들이 Java Heap에 거주하기 때문에 가장 많은 메모리를 필요로 하기 때문이다.

하지만 위의 제목처럼 GC Log 등을 통해 모니터링을 해 본 결과 Java Heap의 여유 공간이 충분한데도 OOEM이 난다면? 다음과 같은 세가지 문제를 의심해보아야 한다.

- Permanent Space가 부족하지 않은가?
- Native Heap이 부족하지 않은가?
- 버그가 아닌가? :)

Permanet Space와 Native Heap에서 발생할 수 있는 메모리 부족 현상에 대해서 알아보자.

- Permanent Space의 부족
GC Log를 통해 Permanent Space가 부족한 지의 여부를 간접적으로 판단할 수 있다.
(GC Log에 대한 자세한 내용은 Google 검색....)

대부분의 Application이 기본 크기만으로 필요한 클래스들을 관리할 수 있다. 하지만 복잡한 Application 들, 특히 많은 수의 Servlet/JSP/EJB/Library 들을 로딩하는 Web Application의 경우 좀 더 큰 크기의 Permanent Space를 요구하기도한다.

-verbose:class 옵션을 사용하면 어떤 클래스들이 로딩되는지 확인할 수 있다.

Permanent Space의 부족 현상으로 판명나는 경우에는 -XX:PermSize-XX:MaxPermSize 옵션을 이용해 Permanent Space의 크기를 키워주어야 한다.

- Thread Stack Size가 큰 경우
우리가 Thread를 사용할 때마다 Native Heap에는 Thread가 사용하는 메모리가 할당된다. 시스템마다 기본적으로 할당되는 크기는 다르다.

Thread Stack의 크기를 256K라고 가정해보자. 4개의 Thread는 1M를 사용하고, 400개의 Thread는 무려 100M를 사용한다. 수많은 Thread를 사용하는 대형 시스템에서는 결코 간과할 수 없는 크기가 된다.

Application 모니터링을 통해 현재 생성한(사용 중인 아닌) 전체 Thread의 개수를 파악해야 한다. 만일 지나치게 많은(수백개 ~ 수천개) Thread가 생성되었다면 지나치게 큰 크기의 Native Heap을 사용하고 필연적으로 OOEM을 유발한다.

Thread 개수를 줄이는 가장 기본적인 방법은 Thread Pool을 사용하는 것이다. Weblogic/Jeus/Websphere와 같은 WAS들이 수백~수천의 동시 사용자를 감당할 수 있는 것은 Thread Pool을 잘 사용하기 때문이다. 대량의 Client와 통신을 수행하는 Server Application을 작성하는 경우에는 반드시 Thread Pool 기법을 사용해서 실제 생성되는 Thread의 개수를 줄여야 한다.

또 다른 방법은 Thread Stack Size를 줄이는 것이다. Thread 개수를 줄일 수 없다면 -Xss128K 정도의 작은 값을 부여해서 메모리 사용량을 줄일 수 있다. 단, Stack 크기가 줄어든 만큼 Stack Overflow 에러가 날 확률이 높아진다.

(PS) Application이 사용하는 Thread 개수를 모니터링하는 가장 좋은 방법은? Thread Dump(kill -3)가 가장 손쉽고 확실한 방법이다. JDK 1.5에서 추가된 Platform MBean(MXBean)과 JConsole 또한 좋은 방법이다. JConsole에 대해서는 아래 URL을 참조한다.

http://java.sun.com/developer/technicalArticles/J2SE/jconsole.html

- File나 Socket을 지나치게 많이 오픈하는 경우
File/Socket을 Resource Limit를 초과하여 오픈하는 경우에도 OOEM이 발생한다. 우선 File이나 Socket을 열고 닫지 않은, 이른바 Resource Leak을 의심해봐야 하며 필요한 경우 다음과 같이 File/Socket의 Resource Limit을 키워야 한다.

ulimit -n 10000

- JNI를 사용하는 Library들...
JDK가 제공하는 Library나 3rd Party가 제공하는 Library들 중에서 JNI를 사용하는 경우 Native Heap을 사용한다. Native Heap은 Java Heap과는 전혀 독립적으로 사용된다. 따라서 Java Heap은 여유가 있음에도 OOEM이 발생하게 된다.

Max Heap(-Xmx) 크기를 500M 정도로 지정했는데 OS 모니터링을 통해 본 Java Process의 메모리 크기가 2G라면? 십중 팔구 Native Heap의 크기가 지나치게 커진 것이다. Thread Stack 크기와 더불어 JNI Heap을 의심해보아야 한다.

Oracle OCI JDBC Driver가 JNI를 사용하는 대표적인 3rd Party Library이다. OCI JDBC Driver는 Thin Driver에 비해 성능 면에서 다소 유리하지만 Native Heap 공간을 많이 사용하는 경향이 있다. 따라서 OCI Driver를 사용하는 경우에는 Process의 메모리 크기를 잘 모니터링해야 한다.

한가지 역설적인 것은 Native Heap을 좀더 크게 사용하기 위해서 Java Heap의 크기를 줄여야 하는 경우가 있다는 것이다. 즉, OutOfMemory 부족 현상이 Native Heap에서 발생하는 경우에는 Java Heap의 크기를 줄이는 것이 대안이 될 수 있다. 32bit 환경에서는 하나의 Java 프로세스가 사용할 수 있는 최대 메모리 공간은 2G로 제한된다. 이 공간을 Java Heap이 다 써버리면 Native Heap이 사용될 수 있는 공간이 그만큼 줄어든다. 그만큼 OOEM이 날 확률이 높아진다.

- 노파심에...
시스템의 물리적 메모리가 2G이다. Java Application의 성능을 극대화하기 위해 Max Heap Size를 1.8G 정도 부여할려고 한다. 바람직한가? 그럴 수도 있지만 생각치 못한 역효과가 있을 수 있다. 앞에서 소개한 몇가지 사례를 기억하자.

Java Heap에 지니치게 많은 메모리를 할당함으로써 Permanet Space나 Native Heap의
부족을 초래하게 되고 이로 인해 OOEM이나 Paging In/Out에 의한 성능 저하 현상이 유발될 수 있기 때문이다.

메모리는 항상 필요한 만큼만...

--------------------------------------------------------------------------------------------------------
다음 글에 계속

신고
tags : GC, Heap, java, OutOfMemory
Trackback 0 : Comment 0

Write a comment


[Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part2

Enterprise Java 2007.09.12 17:59
2. Paging In/Out에 의한 GC 지연

가끔 다음과 같은 현상이 발생하는 경우가 있다.

  • 평소에는 Full GC가 1초안에 끝났다. GC에 의해 Heap 사용량은 200M -> 100M 로 줄었다.
  • 그런데 어제 갑자기 Full GC가 20여초가 걸렸다. Heap 사용량의 변화는 210M -> 100M로 평소와 거의 비슷했다.
도대체 무슨 일이 벌어진 것인가?
정확한 원인을 GC log만을 보고 분석하기란 불가능하다. Full GC가 처리해야할 메모리의 양은 거의 비슷하다. 하지만 Full GC 소요시간은 20배가 늘었다. 논리적으로 가능한 이유들을 열거해 보면...
  • Full GC 당시 CPU Load가 심해서 GC 작업이 지연되었다 <-- CPU 문제
  • Full GC 당시 Memory Load가 심해서 Heap 영역이 Page Out 되었다 <-- Memory 문제
  • JVM 버그다 <-- Bug 데이터베이스 검색!!
다행히(?) 의외로 적지 않은 경우 2번째 이유, 즉 Paging In/Out에 의한 GC 지연이 발생한다.

아래에 실제로 발생한 사례가 있다.

다음과 같이 Low Pause Collector를 사용하는 상황에서...

-XX:+UseConMarkSweepGC -Xms2028m -Xmx2028m

New Generation Collection에 30초, Concurrent Mode가 구동되어서 총 78초가 흐르고 실패하고 말았다.

30263.967: [ParNew: 22279K->3192K(57344K), 30.0028214 secs]
30293.970: [CMS (concurrent mode failure): 1507043K->1045599K(2031616K), 78.8167675 secs]
....

위의 GC Log를 보면 한눈에 비정상적인 상황임을 알 수 있다.
  • 첫째, 57M의 New Generation을 정리하는데 무려 30초가 걸렸다.
  • 둘째, CMS(concurrent mode failure)가 무려 78초가 흐른 후 실패하고 말았다. Concurrent mode failure란 Tenured Space가 꽉 차기 전에 Concurrent Mode의 Collection 작업이 끝나지 않았다는 것을 의미한다.
다행히 이 현상이 발생한 당시의 OS 모니터링 정보에 의해 메모리 부족 현상에 의해 Paging In/Out이 왕성하게 발생한 것을 확인할 수 있었다.

시도한 Workaround는 Java Max Heap Size를 줄이는 것이었고, 더불어 몇몇 JVM Option이 수정되었다. Max Heap Size를 줄인 이유는 Java Process가 사용하는 메모리를 줄임으로써 OS에 메모리의 여유분을 주기 위해서이다.

비록 Java가 메모리 관리를 상당히 자동화하지만, 여전히 OS에 종속된 플랫폼이라는 것을 명심해야 한다. 따라서 OS 레벨의 CPU/Memory/IO 모니터링과 Java Heap Monitoring을 병행해야만 좀 더 합리적인 성능 문제 분석을 수행할 수 있다.

-----------------------------------------------------------------------------------------------
다음 글에 계속


신고
Trackback 0 : Comment 0

Write a comment


[Enterprise Java는 거대한 동기화 머신이다] - 재미있는 GC 성능 사례 - Part1

Enterprise Java 2007.09.10 22:09
Java에서의 Garbage Collection을 흔히 필요악으로 묘사한다. 확실히 GC는 편리한 객체 사용이라는 장점을 제공한다. 하지만 Java에서 발생하는 성능 저하 현상의 8,90%는 GC와 직간접적으로 관련이 있다고 해도 무방할 정도로 문제를 일으키기도 한다.

Garbage Collection은 [맹견]과 같다. 잘 길들이면 행복을 주지만, 자칫 치명적인 상처를 입힐 수도 있다.

GC에서 문제가 발생하는 상황은 매우 다양하다. 더구나 각 시스템마다 Unique한 성능 특징을 가지고 있어 일반적인 해결책이 무용한 경우가 많다.

하지만, 보편적으로 발생하는 몇 가지 사례를 통해 의미있는 통찰력을 얻을 수 있다는 사실은 확실하다. 이런 의미에서 앞으로 몇 차례에 걸쳐 전형적이면서 재밌는 GC 사례와 해결책을 논의해보고자 한다.


1. RMI 사용에 의한 주기적인 Full GC 발생

RMI를 사용할 경우 주기적으로(정확하게 말하면 60초마다) System.gc()를 호출한다.

아래의 GC Dump 예를 보자.

...
211.207: [Full GC 211.207: [ParNew: 123251K->24523K(742784K), 0.2391338 secs] ...
278.167: [Full GC 278.167: [ParNew: 140194K->3468K(742784K), 0.9600674 secs] ...
342.531: [Full GC 342.531: [ParNew: 81241K->646K(742784K), 0.5440857 secs] ...
...

위의 예를 보면 278 - 211 = 67(초), 342 - 278 = 64(초)로 항상 60여 초 단위로 Full GC가 발생하고 있다. 이런 현상이 목격되면 RMI에서 사용하는 Distributed GC에 의한 Explicit GC일 가능성이 대부분이다. RMI 통신을 위해 생성된 객체들을 주기적으로 정리하기 위해 Distributed GC가 작동하게 된다.

아래 2개의 옵션이 Distributed GC에 의한 Explicit GC의 간격을 결정한다.

sun.rmi.dgc.server.gcInterval
sun.rmi.dgc.client.gcInterval

JDK 1.6 이전에는 이 옵션들의 기본값이 60000(ms), 즉 60초였다. 60초마다 한번씩 System.gc()를 호출하게 된다.

System.gc() 호출에 의한 Explicit GC 작업은 Collector의 종류와 무관하게 항상 STW(Stop-The-World) 방식의 Full GC를 유발한다. 심지어 Low Pause Collector(-XX:+UseConcMarkSweepGC)를 사용하더라도 System.gc()는 여전히 STW 방식으로 작동한다. 큰 크기의 Heap을 사용하는 Application에서는 이런 빈번한 Full GC의 호출이 큰 성능 문제를 일으킨다.

기본적인 가이드는 다음과 같다.

1. -XX:+DisableExplicitGC 옵션을 사용해서 System.gc() 콜을 무의미하게 만들어 버린다. 가장 극단적이고 확실한 해결책이다.
2. -Dsun.rmi.dgc.server.gcInterval=3600000 -Dsun.rmi.dgc.client.gcInterval=3600000 (한시간) 과 같이 DGC Interval을 크게 준다.

JDK 1.6 부터는 Low Pause Collector(Concurrent Collector, -XX:+UseConcMarkSweepGC)를 사용할 경우 다음 옵션을 사용할 수 있다.
3. -XX:+ExplicitGCInvokesConcurrent 옵션을 사용해서 System.gc() 콜이 STW(Stop-The-World) 방식이 아닌 Concurrent 방식으로 이루어지도록 한다.


Distributed GC를 논외로 하더라도 Explicit GC는 절대로 남용되어서는 안된다. 메모리를 많이 사용하는 Application들에서 메모리를 좀 더 효율적으로 사용하기 위해 System.gc()를 틈틈이 호출하는 코드를 삽입하는 오류를 흔히 보게 되는데, 굉장히 잘못되고 위험한 방식이다.

Java의 자동화된 GC는 Explicit GC의 호출을 거의 필요로 하지 않는다. 따라서 무의미한 System.gc() 호출이 발생하지 않도록 해야 한다.

PS) 그렇다면, Explicit GC는 완전히 무용한 것일까? 흐음...
생각해 볼 문제다. 다음과 같은 경우에는 유용할 수도 있다.
-XX:+UseConcMarkSweepGC에 의해 활성화되는 Low Pause Collector는 Full GC를 Concurrent하게 진행한다. 이것을 가능하게 하기 위해 Compaction(압축) 작업을 하지 않는다. 따라서 Low Pause Collector에서는 Fragmentation이 발생할 확률이 높다.
Fragmentation이 지나쳐서 필요한 메모리를 확보하지 못하면 STW 방식의 Full GC가 발동되고, 비로소 Compaction 작업이 이루어진다. 웁스!!! 만일 이런 일이 시스템에 로드가 많이 걸린 시점에 발생했다면? Concurrent Collector의 장점이 사라져 버리는 것이다.

Low Pause Collector를 사용하는 환경에서 Fragmentation에 의한 STW Full GC가 자주 발생한다고 판명되면, 시스템의 로드가 적은 시점에 주기적으로 System.gc()를 호출하는 것도 한가지 솔루션이 될 수 있다. 아주 특수한 경우이지만 JVM 옵션으로도 해결이 안되는 경우에는 Workaround가 될 수 있다는 의미이다. 물론 정교한 JVM 옵션 설정으로 이런 문제가 생기지 않도록 하는 것이 최선이겠지만...




신고
Trackback 0 : Comments 3
  1. 욱짜 2007.09.11 17:25 신고 Modify/Delete Reply

    (참고) JMX를 사용하는 경우 RMI에 의한 Full GC가 자연스럽게 생기니 특히 주의가 필요합니다. 다행히 JDK 1.6에서는 DGC Interval이 1시간으로 늘었지만 이전 버전이라면 반드시 확인 요망!!

  2. 아쭈 2007.11.12 21:37 신고 Modify/Delete Reply

    퍼가겠습니다^^좋은 글 감사합니다^^

  3. 쫑맹 2012.03.29 11:10 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment

티스토리 툴바