potential causes of long remark pause?

Fri Apr 10 17:24:58 UTC 2015

Including the hotspot-gc-use.

On 4/10/2015 10:23 AM, Jon Masamitsu wrote:
> Brian,
>
> It looks like the weak reference processing.
>
> 2015-04-09T12:36:38.313-0700: [Rescan (parallel) , 0.0218780 secs]2015-04-09T12:36:38.334-0700:[weak refs processing, 5.0944360 secs]
>
> If you turn on PrintReferenceGC, you might get more information.
> If you usually see long reference processing times, try
> turning on ParallelRefProcEnabled.  But if you only see
> very intermittent spikes in reference processing times,
> it might not be worth it (the parallel overhead will slow
> down the remark times).
>
> Jon
>
> On 4/9/2015 3:07 PM, Brian Williams wrote:
>> I'm looking for ideas on what would lead to a 5 second CMS Remark pause. Looking through previous GC logs, the largest remark pause I could find was .58 seconds, with the average being .15. The snippet of the GC log that covers the full CMS cycle is below.
>>
>> We're using Java 1.7.0_55 running on "Linux 2.6.32-431.29.2.el6.x86_64 amd64" with 24 virtual CPUs.
>>
>> Here are the JVM options as reported by -XX:+PrintCommandLineFlags:
>>
>> -XX:+CMSConcurrentMTEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:CMSMaxAbortablePrecleanTime=3600000 -XX:+CMSParallelRemarkEnabled -XX:+CMSParallelSurvivorRemarkEnabled -XX:+CMSScavengeBeforeRemark -XX:ConcGCThreads=6 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=94489280512 -XX:MaxHeapSize=94489280512 -XX:MaxNewSize=2147483648 -XX:MaxTenuringThreshold=6 -XX:NewSize=2147483648 -XX:OldPLABSize=16 -XX:PermSize=67108864 -XX:+PrintCommandLineFlags -XX:PrintFLSStatistics=1 -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:RefDiscoveryPolicy=1 -XX:+UseBiasedLocking -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
>>
>> And the details of the CMS collection with the long remark pause:
>>
>> 2015-04-09T12:36:10.393-0700: [GC [1 CMS-initial-mark: 45088837K(90177536K)] 45111889K(92065024K), 0.0296420 secs] [Times: user=0.01 sys=0.00, real=0.03 secs]
>> 2015-04-09T12:36:24.055-0700: [CMS-concurrent-mark: 13.633/13.633 secs] [Times: user=75.95 sys=2.86, real=13.63 secs]
>> 2015-04-09T12:36:24.371-0700: [CMS-concurrent-preclean: 0.315/0.315 secs] [Times: user=0.44 sys=0.02, real=0.32 secs]
>> 2015-04-09T12:36:29.659-0700: [GCBefore GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 1476244390
>> Max   Chunk Size: 1476244390
>> Number of Blocks: 1
>> Av.  Block  Size: 1476244390
>> Tree      Height: 1
>> Before GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 0
>> Max   Chunk Size: 0
>> Number of Blocks: 0
>> Tree      Height: 0
>> 2015-04-09T12:36:29.660-0700: [ParNew: 1680929K->4322K(1887488K), 0.0794930 secs] 46769766K->45093205K(92065024K)After GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 1476237004
>> Max   Chunk Size: 1476237004
>> Number of Blocks: 1
>> Av.  Block  Size: 1476237004
>> Tree      Height: 1
>> After GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 0
>> Max   Chunk Size: 0
>> Number of Blocks: 0
>> Tree      Height: 0
>> , 0.0797770 secs] [Times: user=1.40 sys=0.00, real=0.08 secs]
>> 2015-04-09T12:36:38.230-0700: [CMS-concurrent-abortable-preclean: 13.774/13.859 secs] [Times: user=18.14 sys=0.50, real=13.86 secs]
>> 2015-04-09T12:36:38.232-0700: [GC[YG occupancy: 845557 K (1887488 K)]2015-04-09T12:36:38.232-0700: [GCBefore GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 1476237004
>> Max   Chunk Size: 1476237004
>> Number of Blocks: 1
>> Av.  Block  Size: 1476237004
>> Tree      Height: 1
>> Before GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 0
>> Max   Chunk Size: 0
>> Number of Blocks: 0
>> Tree      Height: 0
>> 2015-04-09T12:36:38.232-0700: [ParNew: 845557K->4086K(1887488K), 0.0805340 secs] 45934440K->45093032K(92065024K)After GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 1476225574
>> Max   Chunk Size: 1476225574
>> Number of Blocks: 1
>> Av.  Block  Size: 1476225574
>> Tree      Height: 1
>> After GC:
>> Statistics for BinaryTreeDictionary:
>> ------------------------------------
>> Total Free Space: 0
>> Max   Chunk Size: 0
>> Number of Blocks: 0
>> Tree      Height: 0
>> , 0.0808020 secs] [Times: user=1.42 sys=0.00, real=0.08 secs]
>> 2015-04-09T12:36:38.313-0700: [Rescan (parallel) , 0.0218780 secs]2015-04-09T12:36:38.334-0700: [weak refs processing, 5.0944360 secs]2015-04-09T12:36:43.429-0700: [scrub string table, 0.0013140 secs] [1 CMS-remark: 45088945K(90177536K)] 45093032K(92065024K), 5.3492750 secs] [Times: user=6.98 sys=0.00, real=5.35 secs]
>> CMS: Large Block: 0x00007f8e42f4aed0; Proximity: 0x0000000000000000 -> 0x00007f8e276f5b08
>> CMS: Large block 0x00007f8e42f4aed0
>> 2015-04-09T12:36:55.505-0700: [CMS-concurrent-sweep: 11.913/11.924 secs] [Times: user=16.93 sys=0.26, real=11.93 secs]
>> 2015-04-09T12:36:55.703-0700: [CMS-concurrent-reset: 0.187/0.187 secs] [Times: user=0.21 sys=0.00, real=0.19 secs]
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150410/d784dfe1/attachment.html>