Проблема приостановки сжатия GC в jrockit
Ниже мой параметр приложения JAVA_OPTS в jrocket .
> -DRMIEngine -Xms10G -Xmx10G -Xns:1g -Xgc:pausetime -XpauseTarget:201 -XXgcTrigger=20
> -Xgc:gencon -XXkeepAreaRatio:50 -XXcompactRatio:10 -Xverbose:memory -Xverbose:gcreport -Xverbose:compaction -Xverbose:gcpause -xverboselog:${HOME}/bin/GCLOG/verbose-jrockit-server.log
> -Xverbosetimestamp -Delite.serverinstace=PRIMARY_4 -Djava.rmi.server.hostname=10.25.59.31
> -Djava.rmi.activation.port=3232 -Dcom.sun.management.jmxremote
> -Dcom.sun.management.jmxremote.port=8874 -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false -Doracle.net.disableOob=true
Здесь я приложил GC журнал приложения. Мы сделали анализ, когда сжатие выполняется в куче. В это время приложение получает паузу в течение почти 52 секунд. Это сжатие прерывается из-за тайм-аута. Так что, если кто-то может помочь мне выяснить причину, почему это сжатие прерывается, и приложение получает столько времени паузы.
Ниже приведен фрагмент журнала для 52-секундной паузы.
> [compact][Wed Mar 15 13:36:50 2017][05297] [OC#1175] Compaction
> reason: Normal.
>
> [compact][Wed Mar 15 13:36:50 2017][05297] [OC#1175] Compacting 409 of
> 4096 parts at index 3687. Compaction type is external. Exceptional:
> No.
>
> [compact][Wed Mar 15 13:36:50 2017][05297] [OC#1175] Compaction area
> start: 0x340180000, end: 0x380000000. Timeout: 80.400 ms.
>
> [compact][Wed Mar 15 13:36:50 2017][05297] [OC#1175] Compactset limit
> (per thread): 22611163 (dynamic), using matrixes.
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Average compact
> time ratio (move phase/total time): 1.000000.
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Compaction time,
> total: 28.157 ms (target 80.400 ms).
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Compaction moved
> 9331 objects and left 34 objects. Total moved size 908576B.
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Compaction added
> 1072117928B of free memory in 18 parts.
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Found 20148
> references.
>
> [compact][Wed Mar 15 13:37:50 2017][05297] [OC#1175] Updated 10591
> references.
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [---] 62415.309
> ms (1771992.078000-1772054.493000) OC
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [con] 0.002
> ms (1771992.078000-1771992.078000) OC:PreGC
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [pau] 325.399
> ms (1771992.078000-1771992.403000) OC:Initial
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [con] 5201.610
> ms (1771992.403000-1771997.605000) OC:ConcurrentMark
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [pau] 336.194
> ms (1771997.605000-1771997.942000) OC:Main
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [con] 258.891
> ms (1771997.942000-1771998.201000) OC:ConcurrentSweep1
>
[gcpause] [Ср. 15 марта 13:37:53 2017][05297] [OC#1175] [pau] 52942.776
> ms (1771998.201000-1772051.144000) OC:SweepSwitch
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [con] 247.626
> ms (1772051.144000-1772051.392000) OC:ConcurrentSweep2
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [pau] 2.055
> ms (1772051.392000-1772051.395000) OC:Cleanup
>
> [gcpause][Wed Mar 15 13:37:53 2017][05297] [OC#1175] [con] 3098.431
> ms (1772051.395000-1772054.493000) OC:PostGC
>
> [memory ][Wed Mar 15 13:37:53 2017][05297] [OC#1175]
> 1771992.078-1772054.493: OC 8574661KB->3276276KB (10485760KB), 62.415 s, sum of pauses 53606.424 ms, longest pause 52942.776 ms.
А ниже находится строка, которую вы можете искать в журнале, если сжатие прервано.
[compact] [Ср 15 марта 18:44:23 2017][05297] [OC#1189] Сжатие было прервано в 0x240780050, нет свободной кучи для внешнего уплотнения
[compact] [Ср 15 марта 19:03:58 2017][05297] [OC#1190] Сжатие было прервано в 0x1014eb4e8, сжатие достигло предельного времени