Long Pause During Sweep Switch in Jrockit Old Collection

Question

I am facing issue with long pauses during sweep switch of old collection in Jrockit, which is making my application unresponsive for seconds

Jrockit Version: R28.3.12-8

Configuration:

JAVA_OPTS="-Xms10G -Xmx10G -Xns:2g -Xgc:pausetime -XpauseTarget:201 
-XXgcTrigger=40 -Xgc:gencon -XXkeepAreaRatio:50 -XXcompactRatio:10 
-XX:NurseryPartsLimit=0 -Xverbose:memory -Xverbose:memdbg -Xverbose:gcreport 
-Xverbose:compaction -Xverbose:gcpause -Xverbosetimestamp"

Logs:

[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] GC reason: GC trigger reached.
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] 93025.657: OC started.
[alloc  ][Sun Nov 12 20:17:49 2017][24155] [OC#197] Pending requests at 'Before OC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.
[compact][Sun Nov 12 20:17:49 2017][24155] [OC#197] Compaction reason: Normal.
[compact][Sun Nov 12 20:17:49 2017][24155] [OC#197] Compacting 409 of 4096 parts at index 3687. Compaction type is external. Exceptional: No.
[compact][Sun Nov 12 20:17:49 2017][24155] [OC#197] Compaction area start: 0x340180000, end: 0x380000000. Timeout: 80.400 ms.
[compact][Sun Nov 12 20:17:49 2017][24155] [OC#197] Compactset limit (per thread): 22611163 (dynamic), using matrixes.
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] Starting initial marking phase (OC1).
[nursery][Sun Nov 12 20:17:49 2017][24155] [OC#197] Young collection started. This YC is a part of OC#197 initial marking.
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] SemiRef phase WeakJNIHandles run in single threaded mode.
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] SemiRef phase ClassConstraints run in single threaded mode.
[nursery][Sun Nov 12 20:17:49 2017][24155] [OC#197] Next keeparea will start at 0x312f60260 and end at 0x358ad2cd0.
[alloc  ][Sun Nov 12 20:17:49 2017][24155] [OC#197] Satisfied 0 object and 0 tla allocations. Pending requests went from 0 to 0.
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] Initial marking phase promoted 1164528 objects (70750KB).
[memory ][Sun Nov 12 20:17:49 2017][24155] [OC#197] Starting concurrent marking phase (OC2).
[memory ][Sun Nov 12 20:17:49 2017][24155] Adding 3 final handles from dying thread 'RMI RenewClean-[10.25.59.11:887'.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Concurrent mark phase lasted 4793.797 ms.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Starting precleaning phase (OC3).
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Precleaning phase lasted 53.837 ms.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Starting final marking phase (OC4).
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Young collection started. This YC is a part of OC#197 final marking.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] SemiRef phase WeakJNIHandles run in single threaded mode.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] SemiRef phase ClassConstraints run in single threaded mode.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] SemiRef phase FinalMemleak run in single threaded mode.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Next keeparea will start at 0x312f60260 and end at 0x358ad2cd0.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Final marking phase promoted 246414 objects (15380KB).
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Adding 34 temporary work packets to permanent pool, now 2423 packets.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Total mark time: 5512.803 ms.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Ending marking phase.
[memory ][Sun Nov 12 20:17:54 2017][24155] [OC#197] Starting concurrent sweeping phase.
[compact][Sun Nov 12 20:17:54 2017][24155] [OC#197] External compaction aborted due to timeout after 122.521959 ms at address 0x3522f7848.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Setting keepAreaMarkers[0] to 0x2cf0e6c80.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Setting keepAreaMarkers[1] to 0x305ba15d8.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Setting keepAreaMarkers[2] to 0x33a3ba318.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Next keeparea will start at 0x305ba15d8 and end at 0x33a3ba318.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Nursery size increased from 0KB to 1659304KB. Nursery list consists of 19491 parts.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Average part size: 85KB. Contraharmonic mean (CHM): 4259KB. CHM per part: 0KB. Normalized CHM: 0.002567.
[memory ][Sun Nov 12 20:17:54 2017][24155] Adding 3 final handles from dying thread 'RMI RenewClean-[10.25.59.11:887'.
[nursery][Sun Nov 12 20:19:21 2017][24155] [OC#197] Nursery size increased from 1659304KB to 2097155KB. Nursery list consists of 91212 parts.
[nursery][Sun Nov 12 20:19:21 2017][24155] [OC#197] Average part size: 23KB. Contraharmonic mean (CHM): 3426KB. CHM per part: 0KB. Normalized CHM: 0.001634.
[alloc  ][Sun Nov 12 20:19:21 2017][24155] [OC#197] Satisfied 0 object and 0 tla allocations. Pending requests went from 0 to 0.
[nursery][Sun Nov 12 20:19:22 2017][24155] [OC#197] Nursery size remains at 2097155KB. Nursery list consists of 91212 parts.
[nursery][Sun Nov 12 20:19:22 2017][24155] [OC#197] Average part size: 23KB. Contraharmonic mean (CHM): 3426KB. CHM per part: 0KB. Normalized CHM: 0.001634.
[memory ][Sun Nov 12 20:19:22 2017][24155] [OC#197] Total sweep time: 87871.212 ms.
[memory ][Sun Nov 12 20:19:22 2017][24155] [OC#197] Ending sweeping phase.
[nursery][Sun Nov 12 20:19:22 2017][24155] [OC#197] Nursery size remains at 2097155KB. Nursery list consists of 91212 parts.
[nursery][Sun Nov 12 20:19:22 2017][24155] [OC#197] Average part size: 23KB. Contraharmonic mean (CHM): 3426KB. CHM per part: 0KB. Normalized CHM: 0.001634.
[alloc  ][Sun Nov 12 20:19:22 2017][24155] [OC#197] Satisfied 0 object and 0 tla allocations. Pending requests went from 0 to 0.
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Average compact time ratio (move phase/total time): 1.000000.
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Compaction was aborted at 0x3522f7848, Compaction reached time limit
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Compaction time, total: 125.402 ms (target 122.493 ms).
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Compaction moved 126799 objects and left 1 objects. Total moved size 7486840B.
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Compaction added 303519856B of free memory in 2 parts.
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Found 377865 references.
[compact][Sun Nov 12 20:19:22 2017][24155] [OC#197] Updated 136086 references.
[memory ][Sun Nov 12 20:19:22 2017][24155] [OC#197] GC Trigger is locked at 40.0%.
[alloc  ][Sun Nov 12 20:19:22 2017][24155] [OC#197] Pending requests at 'After OC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [---] 97372.976 ms (93025.657000-93123.030000)  OC
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [con]     0.028 ms (93025.657000-93025.657000)  OC:PreGC
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [pau]   589.431 ms (93025.657000-93026.247000)  OC:Initial
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [con]  4847.240 ms (93026.247000-93031.094000)  OC:ConcurrentMark
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [pau]   208.725 ms (93031.094000-93031.303000)  OC:Main
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [con]   287.101 ms (93031.303000-93031.590000)  OC:ConcurrentSweep1
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [pau] 86757.084 ms (93031.591000-93118.348000)  OC:SweepSwitch
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [con]   473.838 ms (93118.348000-93118.822000)  OC:ConcurrentSweep2
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [pau]    21.112 ms (93119.029000-93119.050000)  OC:Cleanup
[gcpause][Sun Nov 12 20:19:26 2017][24155] [OC#197] [con]  3979.846 ms (93119.050000-93123.030000)  OC:PostGC
[memory ][Sun Nov 12 20:19:26 2017][24155] [OC#197] Page faults before OC: 13, page faults after OC: 13, pages in heap: 2621440.
[memory ][Sun Nov 12 20:19:26 2017][24155] [OC#197] Nursery size after OC: 2097155KB. (Free: 1729809KB Parts: 91212)
[memory ][Sun Nov 12 20:19:26 2017][24155] [OC#197] 93025.657-93123.030: OC 6132697KB->3446883KB (10485760KB), 97.373 s, sum of pauses 87576.352 ms, longest pause 86757.084 ms.

My application usually takes under 1 sec to finish a Old Collection, the only difference which I can see between a normal Old collection and this time taking old collection is that when nursery created during normal collection it is given 2GB in first create, while in the long running one nursery is allocated 2GB is two parts

Normal:

[nursery][Sun Nov 12 19:54:50 2017][24155] [OC#196] Nursery size increased from 0KB to 2097152KB. Nursery list consists of 21544 parts.
[nursery][Sun Nov 12 19:54:50 2017][24155] [OC#196] Average part size: 97KB. Contraharmonic mean (CHM): 11149KB. CHM per part: 1KB. Normalized CHM: 0.005316.
[memory ][Sun Nov 12 19:54:50 2017][24155] Adding 3 final handles from dying thread 'RMI RenewClean-[10.25.59.11:887'.
[nursery][Sun Nov 12 19:54:50 2017][24155] [OC#196] Nursery size remains at 2097152KB. Nursery list consists of 21544 parts.

Long Running:

[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Nursery size increased from 0KB to 1659304KB. Nursery list consists of 19491 parts.
[nursery][Sun Nov 12 20:17:54 2017][24155] [OC#197] Average part size: 85KB. Contraharmonic mean (CHM): 4259KB. CHM per part: 0KB. Normalized CHM: 0.002567.
[memory ][Sun Nov 12 20:17:54 2017][24155] Adding 3 final handles from dying thread 'RMI RenewClean-[10.25.59.11:887'.
[nursery][Sun Nov 12 20:19:21 2017][24155] [OC#197] Nursery size increased from 1659304KB to 2097155KB. Nursery list consists of 91212 parts.

Thanks in advance for any kind of help