Below is my application JAVA_OPTS parameter in 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
Here i have attached GC log of application. We have done analysis that when Compaction is done on heap. At that time application get pause for almost 52 second.This compaction get aborted due to timeout. So if anyone can help me findout the reason that why this compaction is get aborted and application get this much time of pause.
Below is log snippet for 52 second pause.
> [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][Wed Mar 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.
And below is string which you can search in log for compaction aborted.
[compact][Wed Mar 15 18:44:23 2017][05297] [OC#1189] Compaction was aborted at 0x240780050, No free heap for external compaction
[compact][Wed Mar 15 19:03:58 2017][05297] [OC#1190] Compaction was aborted at 0x1014eb4e8, Compaction reached time limit
