2012-08-03 3 views
3

경미한 GC 일시 중지 시간이 증가하고 있습니다. 응용 프로그램은 Java로 작성된 서버로 초당 500 회의 트랜잭션을 실행합니다. CMS 수집 후 일시 중지 시간이 이면이 감소하지만 일시 중지 시간이 다시 증가하면 다시 증가합니다. vmstat으로 스왑 사용을 확인했지만 스왑 입출력이 없습니다.보조 GC 일시 중지 시간이 증가하고 있습니다. 가능한 이유는 무엇입니까?

사소한 gc 일시 중지 시간이 증가 할 수있는 이유는 무엇입니까? (0.01 초) 마이너 GC 휴지 시간은 오래 동안 아래

 
{Heap before GC invocations=123 (full 0): 
par new generation total 306688K, used 275101K [0xfffffffe80010000, 0xfffffffe94cd0000, 0xfffffffe94cd0000) 
    eden space 272640K, 100% used [0xfffffffe80010000, 0xfffffffe90a50000, 0xfffffffe90a50000) 
    from space 34048K, 7% used [0xfffffffe92b90000, 0xfffffffe92df7718, 0xfffffffe94cd0000) 
    to space 34048K, 0% used [0xfffffffe90a50000, 0xfffffffe90a50000, 0xfffffffe92b90000) 
concurrent mark-sweep generation total 3243264K, used 71097K [0xfffffffe94cd0000, 0xffffffff5ac10000, 0xffffffff5ac10000) 
concurrent-mark-sweep perm gen total 262144K, used 30336K [0xffffffff5ac10000, 0xffffffff6ac10000, 0xffffffff6ac10000) 
2012-07-29T20:00:19.790+0300: 472.781: [GC 472.782: [ParNew 
Desired survivor size 17432576 bytes, new threshold 4 (max 4) 
- age 1: 1068432 bytes, 1068432 total 
- age 2:  296272 bytes, 1364704 total 
- age 3:  68624 bytes, 1433328 total 
- age 4:  53776 bytes, 1487104 total 
: 275101K->2187K(306688K), 0.0111305 secs] 346199K->73301K(3549952K), 0.0127033 secs] [Times: user=0.13 sys=0.01, real=0.01 secs] 
Heap after GC invocations=124 (full 0): 
par new generation total 306688K, used 2187K [0xfffffffe80010000, 0xfffffffe94cd0000, 0xfffffffe94cd0000) 
    eden space 272640K, 0% used [0xfffffffe80010000, 0xfffffffe80010000, 0xfffffffe90a50000) 
    from space 34048K, 6% used [0xfffffffe90a50000, 0xfffffffe90c72dc0, 0xfffffffe92b90000) 
    to space 34048K, 0% used [0xfffffffe92b90000, 0xfffffffe92b90000, 0xfffffffe94cd0000) 
concurrent mark-sweep generation total 3243264K, used 71114K [0xfffffffe94cd0000, 0xffffffff5ac10000, 0xffffffff5ac10000) 
concurrent-mark-sweep perm gen total 262144K, used 30336K [0xffffffff5ac10000, 0xffffffff6ac10000, 0xffffffff6ac10000) 
} 

는 GC 로그 파일의 일부이다 : 여기

는 마이너 GC 휴지 시간이 짧은 반면 GC 로그 파일의 일부 (0.9 초)

 
{Heap before GC invocations=38526 (full 3): 
par new generation total 306688K, used 280310K [0xfffffffe80010000, 0xfffffffe94cd0000, 0xfffffffe94cd0000) 
    eden space 272640K, 100% used [0xfffffffe80010000, 0xfffffffe90a50000, 0xfffffffe90a50000) 
    from space 34048K, 22% used [0xfffffffe90a50000, 0xfffffffe911cda60, 0xfffffffe92b90000) 
    to space 34048K, 0% used [0xfffffffe92b90000, 0xfffffffe92b90000, 0xfffffffe94cd0000) 
concurrent mark-sweep generation total 3243264K, used 1023755K [0xfffffffe94cd0000, 0xffffffff5ac10000, 0xffffffff5ac10000) 
concurrent-mark-sweep perm gen total 262144K, used 34997K [0xffffffff5ac10000, 0xffffffff6ac10000, 0xffffffff6ac10000) 
2012-07-31T13:21:46.709+0300: 149360.928: [GC 149360.930: [ParNew 
Desired survivor size 17432576 bytes, new threshold 4 (max 4) 
- age 1: 1794816 bytes, 1794816 total 
- age 2: 2864408 bytes, 4659224 total 
- age 3:  72672 bytes, 4731896 total 
- age 4:  86160 bytes, 4818056 total 
: 280310K->7605K(306688K), 0.9073290 secs] 1304066K->1031418K(3549952K), 0.9100161 secs] [Times: user=9.34 sys=0.15, real=0.91 secs] 
Heap after GC invocations=38527 (full 3): 
par new generation total 306688K, used 7605K [0xfffffffe80010000, 0xfffffffe94cd0000, 0xfffffffe94cd0000) 
    eden space 272640K, 0% used [0xfffffffe80010000, 0xfffffffe80010000, 0xfffffffe90a50000) 
    from space 34048K, 22% used [0xfffffffe92b90000, 0xfffffffe932fd490, 0xfffffffe94cd0000) 
    to space 34048K, 0% used [0xfffffffe90a50000, 0xfffffffe90a50000, 0xfffffffe92b90000) 
concurrent mark-sweep generation total 3243264K, used 1023813K [0xfffffffe94cd0000, 0xffffffff5ac10000, 0xffffffff5ac10000) 
concurrent-mark-sweep perm gen total 262144K, used 34997K [0xffffffff5ac10000, 0xffffffff6ac10000, 0xffffffff6ac10000) 
} 

JVM의 인수 :

 
-d64 -server \ 
-XX:+UseParNewGC \ 
-XX:+UseConcMarkSweepGC \ 
-Xloggc:./logs/gc_"$DATE".log -XX:+PrintGCDetails -XX:+PrintGCDateStamps \ 
-XX:+PrintGC \ 
-XX:PrintCMSStatistics=2 \ 
-XX:+PrintTenuringDistribution \ 
-XX:+PrintHeapAtGC \ 
-XX:+PrintGCTaskTimeStamps \ 
-XX:PermSize=256m -XX:MaxPermSize=256m \ 
-XX:+CMSClassUnloadingEnabled \ 
-XX:-OmitStackTraceInFastThrow \ 
-XX:ParallelGCThreads=16 \ 
-XX:ParallelCMSThreads=12 \ 
-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE -Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE \ 
-Xms3500m -Xmx3500m -Xss192k 
+0

vmstat로 스왑 검사에 관해서는 - 페이징은 결코 JVM에서 문제가되어서는 안됩니다. 또는 우리는 다른 크기의 지연에 관해 이야기 할 것입니다. 위의 gc 시간은 대략 10의 차이 만 있습니다. –

+0

어떤 JVM 버전을 사용하고 있습니까? 이전 버전의 JVM에는 -XX : ParallelCMSThreads> 1의 버그가 있습니다.이 버그는 완전 GC가없이 참조 (weak, soft 등)가 올바르게 처리되지 못하게합니다. 실제로 로그가 이상하게 보입니다. 참조 처리 시간을 확인하려면 -XX : + PrintReferenceGC를 추가하는 것이 좋습니다. 약한 또는 부드러운 참조를 적극적으로 사용하는 응용 프로그램의 경우 원인이 될 수 있습니다. –

+0

JVM 버전은 jdk1.6.0_25입니다. – ilkinulas

답변

0

에덴 공간이 넓어지는 것은 놀랍지 만 싸다. 유지되는 물건을 복사하는 것이 비용이 많이 든다. 당신의 짧은 시간에

당신은 유지 (두 번째 크기) 당신의 긴 시간에

346199K->73301K, 0.0127033 secs 

당신은 당신이 훨씬 유지하기 때문에 GC가 이상했다 첫 번째 경우에, 즉

1304066K->1031418K(3549952K), 0.9100161 secs 

훨씬 더 유지 더 많은 데이터.

내가 이런 경우에 시도한 첫 번째 일은 컬렉션이 발생하기 전에 더 많은 개체가 죽어 버리기를 바라고 에덴 크기를 늘리는 것입니다.

+0

CMS 또는 전체 (시스템) gc가 사소한 gc 일시 중지 시간을 줄이는 이유를 설명 할 수 있습니까? – ilkinulas

+0

전체 GC가 개체를 이전 세대로 이동시킵니다. 이것은 젊은 세대가 더 작아지고 (아마도 거의 비어 있음), 청소하는 데 걸리는 시간이 줄어들 것이라는 것을 의미합니다. 젊은 세대에 더 많은 물체가 추가됨에 따라 다시 청소하는 데 시간이 오래 걸릴 것입니다. –

+0

CMS에는 기본적으로 tenuring threshold가 4로 설정되어 있으며 GC 로그의 두 조각에는 정확히 4 세대의 개체가 있습니다. –

0

새로운 공간 만 300M이고 기존 공간은 3500M입니까?
새 공간의 크기가 커집니다. 가능한 경우 jvm arg를 제공 하시려면
을 제공 하시겠습니까?

+1

질문을 업데이트했습니다. (jvm args 추가) – ilkinulas

관련 문제