g1 notes with adobe coldfusion

Tue Dec 3 14:01:14 PST 2013

Hi Carl,

A couple things strike me as they could (possibly) use fine tuning.

But, to first to address your “threads out of sync” … the difference you’re seeing in min and max Update RS and Processed Buffers do not necessarily mean that the threads were out of sync. It looks like one of the threads spent quite a bit more time updating remembered sets than the others, and that same thread processed a lot more buffers than the others.  Hence, we can make some sense out of why one thread took quite a bit longer than the other threads.  The GC threads will attempt work stealing.  And, based on the termination times,  and termination attempts, it doesn’t look like a particular GC thread or threads were not in a termination protocol for very long while waiting for another to complete.

The Ref Proc time in the Other time looks pretty high.  This suggests your app doing some significant reference processing work.  You should consider adding -XX:+ParallelRefProcEnabled to reduce that Ref Proc time.

I also noticed in the PrintHeapAtGC output you’ve had 65 full GCs.  You might consider investigating where these are coming from, and also look for “to-space overflow” in the GC logs.  When fine tuning G1 GC, I’ve generally found that using -XX:+PrintGCDetails and -XX:+PrintAdaptiveSizePolicy along with -XX:+PrintGC[Date|Time]Stamps to be the most useful, (more so than +PrintHeapAtGC).

If you haven’t already done it, if you do a search for tuning G1 GC you will probably find some helpful G1 tuning presentations from Monica Beckwith, John Cuthbertson and I.  And, you will also probably find a couple good articles on InfoQ by Monica.

Ooh, almost forgot … if you can move to 7u40, you’ll probably see even better results.

hths,

charlie …

On Dec 2, 2013, at 4:57 PM, Carl Meyer <carlmeyer at hotmail.com> wrote:

> 
> Hello,
>  
> I have been using garbage first on some Adobe ColdFusion servers which runs Java 7 (1.7.0_15 natively this particular gc log runs 1.7.0_25). Can I get some commentary on the gc logs?
>  
> When I look at Java via Jconsole or Jvisualvm I notice the heap is more occupied than previous gc - UseParallelGC. This has lead to desirable outcome with the users generally noticing overall improvement in performance which can likely be attributed to their objects residing in memory longer to be referred again and one full gc pause for short duration per day or less than one per day.
>  
> When looking at GC logs I wonder why do a see some threads are out of sync. Here is a log sample:
>  
> {Heap before GC invocations=1712 (full 65):
> garbage-first heap   total 10366976K, used 5739193K [0x0000000567400000, 0x00000007e0000000, 0x00000007e0000000)
>   region size 2048K, 1012 young (2072576K), 25 survivors (51200K)
> compacting perm gen  total 317440K, used 315881K [0x00000007e0000000, 0x00000007f3600000, 0x0000000800000000)
>    the space 317440K,  99% used [0x00000007e0000000, 0x00000007f347a740, 0x00000007f347a800, 0x00000007f3600000)
> No shared spaces configured.
> 947848.595: [GC pause (young), 0.29434754 secs]
>    [Parallel Time: 240.9 ms]
>       [GC Worker Start (ms):  947848595.4  947848595.5  947848595.6  947848595.7
>        Avg: 947848595.6, Min: 947848595.4, Max: 947848595.7, Diff:   0.2]
>       [Ext Root Scanning (ms):  81.5  106.7  109.5  114.4
>        Avg: 103.0, Min:  81.5, Max: 114.4, Diff:  32.9]
>       [Update RS (ms):  44.7  11.9  3.2  11.7
>        Avg:  17.9, Min:   3.2, Max:  44.7, Diff:  41.4]
>          [Processed Buffers : 40 12 13 7
>           Sum: 72, Avg: 18, Min: 7, Max: 40, Diff: 33]
>       [Scan RS (ms):  7.0  6.7  7.0  6.6
>        Avg:   6.9, Min:   6.6, Max:   7.0, Diff:   0.4]
>       [Object Copy (ms):  82.1  89.7  95.3  82.2
>        Avg:  87.3, Min:  82.1, Max:  95.3, Diff:  13.2]
>       [Termination (ms):  0.0  0.1  0.0  0.0
>        Avg:   0.0, Min:   0.0, Max:   0.1, Diff:   0.1]
>          [Termination Attempts : 1 4 5 2
>           Sum: 12, Avg: 3, Min: 1, Max: 5, Diff: 4]
>       [GC Worker End (ms):  947848810.8  947848810.7  947848810.8  947848810.9
>        Avg: 947848810.8, Min: 947848810.7, Max: 947848810.9, Diff:   0.1]
>       [GC Worker (ms):  215.3  215.2  215.2  215.2
>        Avg: 215.2, Min: 215.2, Max: 215.3, Diff:   0.2]
>       [GC Worker Other (ms):  25.7  25.8  25.9  25.9
>        Avg:  25.8, Min:  25.7, Max:  25.9, Diff:   0.2]
>    [Clear CT:   0.7 ms]
>    [Other:  52.7 ms]
>       [Choose CSet:   0.2 ms]
>       [Ref Proc:  41.6 ms]
>       [Ref Enq:   0.3 ms]
>       [Free CSet:   9.8 ms]
>    [Eden: 1974M(1974M)->0B(1972M) Survivors: 50M->52M Heap: 5604M(10124M)->3632M(10124M)]
> [Times: user=0.87 sys=0.06, real=0.30 secs]
> Heap after GC invocations=1713 (full 65):
> garbage-first heap   total 10366976K, used 3719541K [0x0000000567400000, 0x00000007e0000000, 0x00000007e0000000)
>   region size 2048K, 26 young (53248K), 26 survivors (53248K)
> compacting perm gen  total 317440K, used 315881K [0x00000007e0000000, 0x00000007f3600000, 0x0000000800000000)
>    the space 317440K,  99% used [0x00000007e0000000, 0x00000007f347a740, 0x00000007f347a800, 0x00000007f3600000)
> No shared spaces configured.
> }
>  
> Do the differences here (bold) indicate some more G1 tuning is needed to run optimally?
>  
>       [Update RS (ms):  44.7  11.9  3.2  11.7
>        Avg:  17.9, Min:   3.2, Max:  44.7, Diff:  41.4]
>       [Processed Buffers : 40 12 13 7
>        Sum: 72, Avg: 18, Min: 7, Max: 40, Diff: 33]
>  
>    [Other:  52.7 ms]
>       [Choose CSet:   0.2 ms]
>       [Ref Proc:  41.6 ms]
>       [Ref Enq:   0.3 ms]
>       [Free CSet:   9.8 ms]
>  
>  
> Thanks in advance, Carl.
>  
>  
> _______________________________________________
> 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/20131203/98a185a5/attachment-0001.html 