Strange GC behaviour,

[Dang Nhan Nguyen]

I just found out that all the references marked during remark phase are FinalReferences. It's even more strange! -Nhan

From: hotspot-gc-dev-bounces at openjdk.java.net [mailto:hotspot-gc-dev-bounces at openjdk.java.net] On Behalf Of Dang Nhan Nguyen
Sent: Thursday, December 08, 2011 7:20 PM
To: Srinivas Ramakrishna
Cc: hotspot-gc-dev at openjdk.java.net
Subject: RE: Strange GC behaviour,

Hi,

>Actually, prior to the fix for 7112034, there would be potentially fewer Reference objects identified for later >processing (a step known as discovery).
>Following 7112034, there would be potentially more, as some objects not discovered before the fix would be >discovered now.

Agree!

>This is the strange part, and to me does not make sense. How id you determine that (1) there were lots of >Reference objects (2) that a lot
>of time was spent in Reference processing during remark? If you run with -XX:+PrintGCDetails ->XX:+PrintReferenceGC for both the
>cases (with and withouyt -XX:+ParallelRefProcEnabled), we would know what the relative numbers/times looked >like and perhaps
>get closer to what the issue might be here.

Attached cms_lusearch.txt is output of PrintGCDetails which I skipped some ParNew GC part to reduce file size.  The other is my record of number of objects marked in CMS phases. Since I run CMS in stop-the-world fashion (I change code a bit to do so), no object is promoted.
cms_lusearch.log records live objects marked in that phase, I recorded it by increasing the counter everytime an object is marked successfully.

I ran with below command line (don't worry about -XX:CMSInitiatingOccupancyFraction=100 -XX:+UseCMSInitiatingOccupancyOnly. I used it as part of my trick to cause CMS running in foreground):

JAVA_HOME=../ build/linux-amd64/j2sdk-image LD_LIBRARY_PATH=../build/hotspot_product_prof/linux_amd64_compiler2/product ../ build/hotspot_product_prof/linux_amd64_compiler2/product/gamma -Xms100M -Xmx100M -XX:+PrintGCDetails -XX:+PrintReferenceGC -XX:CMSInitiatingOccupancyFraction=100 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseConcMarkSweepGC -XX:ParallelGCThreads=8 -XX:NewRatio=10 -jar dacapo-9.12-bach.jar -s large -n 10 -t 8 lusearch

I recorded high number of objects marked in remark phase. As you can see in the two files, the total number of references reported is around 2-3000 refs during remark. But the number of objects marked during remarked is much more than that: 600k objects (for lusearch application in Dacapo benchmark).
Does this scenario normal?

-Nhan

From: Srinivas Ramakrishna [mailto:ysr1729 at gmail.com]
Sent: Thursday, December 08, 2011 5:15 PM
To: Dang Nhan Nguyen
Cc: hotspot-gc-dev at openjdk.java.net
Subject: Re: Strange GC behaviour,


On Thu, Dec 8, 2011 at 2:41 AM, Dang Nhan Nguyen <nhann at chalmers.se<mailto:nhann at chalmers.se>> wrote:
Hi,

Thank you for your update.
I apply CR is 7112034 and also try with -XX:+ParallelRefProcEnabled:


-    While applying CR is 7112034, CMS still leaves about the same number of objects/ref marked for the remark phase comparing to before applying the CR. Which means the CR make no (or little) change to the number of references  processed during the concurrent marking phase. How can this be explained?

Actually, prior to the fix for 7112034, there would be potentially fewer Reference objects identified for later processing (a step known as discovery).
Following 7112034, there would be potentially more, as some objects not discovered before the fix would be discovered now.

-    When I use -XX:+ParallelRefProcEnabled, performance is worse than not using this option. So, when I enable this, how many threads were used for this reference processing (in a ratio of ParallelGCThreads and ConcGCThreads)?

This is the strange part, and to me does not make sense. How id you determine that (1) there were lots of Reference objects (2) that a lot
of time was spent in Reference processing during remark? If you run with -XX:+PrintGCDetails -XX:+PrintReferenceGC for both the
cases (with and withouyt -XX:+ParallelRefProcEnabled), we would know what the relative numbers/times looked like and perhaps
get closer to what the issue might be here.



>From further information, in one application, 100k-200k references were left to the remark phase, and in  another they are 1.5m references.

May be this is the natural behaviour of your application? One thing we have found to help is if we mak good use of
the survivor spaces, then sometimes these probles will go away because Reference objects get processed
as they become eligible for processing in the young generation (therefore during minor GC's) and thus do not
impose a large monolithic overhead during the less frequent major collections.

-- ramki

Best,
-Nhan

From: Srinivas Ramakrishna [mailto:ysr1729 at gmail.com<mailto:ysr1729 at gmail.com>]
Sent: Thursday, December 08, 2011 2:44 AM
To: Dang Nhan Nguyen
Cc: hotspot-gc-dev at openjdk.java.net<mailto:hotspot-gc-dev at openjdk.java.net>
Subject: Re: Strange GC behaviour,

Hi Nhan --

Make sure you have the recent fix to Reference object processing when doing
MT/Parallel marking with CMS; i don't have the CR handy, but the fix was pushed by
Stefan not long ago. (The workaround was to disable parallel concurrent marking via
-XX:-CMSConcurrentMTEnabled -- but of course the performance impact of that,
depending on yr platform, might compromise yr benchmarking results.)

More inline below:-
On Wed, Dec 7, 2011 at 2:20 PM, Dang Nhan Nguyen <nhann at chalmers.se<mailto:nhann at chalmers.se>> wrote:
Hi guys,

I am benchmarking CMS collector and found it strange that there are many objects left in remark phase.

When I check the issue again by only running foreground CMS (I changed the source code a bit to force CMS running in foreground), so there is no promotion during collecting  (so no objects marked during Preclean and Abortable Preclean phase). Even in this case, I found that there are still many objects left in remark phase (in lusearch and tomcat in Dacapo benchmark, they are 10 times and 1/3 of number of objects marked in concmarking phase, while in suflow, they are just about 100 objects/refs). Most (maybe ALL) of these objects marked in remark phase were processed by refProcessingWork(). In turn, this refProcessingWork() run in single thread mode. The performance was reduced a lot because of this.

-XX:+ParallelRefProcEnabled uses multiple threads to do that phase.


My questions are:
1. What kinds of references were processed by refProcessingWork()? weak and soft ref? what are exactly they are?

all objects of type java.lang.ref.Reference (includes WeakReferencem=, SoftReference, FinalReference, PhantomReference).

2. While I only run CMS in stop-the-world, why are there still many objects left to be processed by remark, in particular here is refProcessingWork()? Why aren't these references/objects processed in concurrent marking phase?

I am not sure I understand the question. What do you mean by "run CMS in stop-the-world"? Note that Reference objects are processed
by all kinds of collectors, young gen (minor) or whole heap (major), stop-world or concurrent. The volume of those objects may
vary a bit between them based on the heap size, NewRatio etc.

hope that helped.
-- ramki

Best,
-Nhan Nguyen


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20111208/78a06e73/attachment.htm>