Garbage Collection - timings and suspension

[Jenny Zhang]

Rohit,

Please see my comments in line.

Thanks
Jenny

On 7/25/2016 8:17 AM, Rohit Mohta wrote:
>
> Hi All,
>
>    Can someone please help me understand the below snippet of Garbage 
> Collection logs?
>
> (a)What’s the importance of values user, sys and real time values? 
>  Should I care about those? For instance in the below snippet, ‘user’ 
> has a value of 0.79second.
>
> My understanding is,
>
> ·‘real’ represents the actual time taken by garbage collector process 
> to actually free up memory i.e. create object graph, and the whole 
> mark-sweep process.
>
Yes, it is the real time to free up the memory. It is the evacuation 
time. It may/maynot include marking, depending on which gc you are using.
>
> ·‘sys’ represents the time spent   in System Space (OS/Kernel related???)
>
yes
>
> ·‘user’ represents the time spent in User space i.e. application.
>
User time is the cpu time in user mode. If you have multiple cpus, and 
use multiple gc threads, user time/real time ratio should be close to 
thenumber of gc threads.
>
> (b)I can see “Stopping threads took: 0.0001230 seconds” statement in 
> numerous occasions. Even when, GC was not taking place.
>
> ·What does it mean by ‘stopping threads took’? Does it mean, garbage 
> collector process was trying to ‘park’ all the threads, without 
> interrupting ongoing instructions. So it had to wait for ongoing 
> processing to complete, before it could put the thread in ‘park’ state?
>
For stop the world gc pauses, all application threads have to be 
stopped. Stopping threads time is the time to bring the threads to a 
safe point so that gc can process.
>
> ·Why does JVM stop application threads even when we don’t see any Full 
> GC events? In my system, full gc event is fired every 60 mins – but I 
> can see the above statement numerous times. Why does that happen?
>
Any stop the world pause need to do that. You might see those for minor gcs.
>
> ·When we talk about GC Suspension time, our definition is – “time for 
> which application will not process anything. Application kinda hangs”. 
> Should we consider these “Total time for which application threads 
> were stopped” also as Suspension time?
>
 From the application point of view, yes.
>
> ·Any best practices to reduce the suspension time (apart from GC 
> friendly code)?
>
You can tune gc so that the stop-the-world time is minimal.
>
> ---------------------------------------------------------------------
>
> 2016-07-22T11:17:35.193+0000: 130991.925: Total time for which 
> application threads were stopped: 0.0014892 seconds, Stopping threads 
> took: 0.0001230 seconds
>
> 2016-07-22T11:18:05.192+0000: 131021.924: Application time: 29.9988249 
> seconds
>
> 2016-07-22T11:18:05.193+0000: 131021.925: Total time for which 
> application threads were stopped: 0.0010031 seconds, Stopping threads 
> took: 0.0001281 seconds
>
> 2016-07-22T11:18:12.845+0000: 131029.577: Application time: 7.6521209 
> seconds
>
> 2016-07-22T13:01:08.837+0000: 137205.569: [Full GC (System.gc()) 
> [PSYoungGen: 9824K->0K(319488K)] [ParOldGen: 321122K->81024K(589824K)] 33
>
> 0946K->81024K(909312K), [Metaspace: 37949K->37949K(1083392K)], 
> 0.1677301 secs] [Times: user=0.79 sys=0.00, real=0.17 secs]
>
> Heap after GC invocations=23415 (full 41):
>
> PSYoungGen      total 319488K, used 0K [0x00000000e7000000, 
> 0x00000000fbc00000, 0x0000000100000000)
>
>   eden space 299008K, 0% used 
> [0x00000000e7000000,0x00000000e7000000,0x00000000f9400000)
>
>   from space 20480K, 0% used 
> [0x00000000fa800000,0x00000000fa800000,0x00000000fbc00000)
>
>   to   space 20480K, 0% used 
> [0x00000000f9400000,0x00000000f9400000,0x00000000fa800000)
>
> ParOldGen       total 589824K, used 81024K [0x00000000b5000000, 
> 0x00000000d9000000, 0x00000000e7000000)
>
>   object space 589824K, 13% used 
> [0x00000000b5000000,0x00000000b9f20000,0x00000000d9000000)
>
> Metaspace       used 37949K, capacity 38526K, committed 38952K, 
> reserved 1083392K
>
>   class space    used 3894K, capacity 4047K, committed 4144K, reserved 
> 1048576K
>
> }
>
> 2016-07-22T13:01:09.005+0000: 137205.737: Total time for which 
> application threads were stopped: 0.1749291 seconds, Stopping threads 
> took: 0.0001236 seconds
>
> ---------------------------------------------------------
>
> Thank You
>
> Rohit
>
> *** AXP - PUBLIC ***
>
> ------------------------------------------------------------------------
> American Express made the following annotations
> ------------------------------------------------------------------------
>
> "This message and any attachments are solely for the intended 
> recipient and may contain confidential or privileged information. If 
> you are not the intended recipient, any disclosure, copying, use, or 
> distribution of the information included in this message and any 
> attachments is prohibited. If you have received this communication in 
> error, please notify us by reply e-mail and immediately and 
> permanently delete this message and any attachments. Thank you."
>
> American Express a ajouté le commentaire suivant le
> Ce courrier et toute pièce jointe qu'il contient sont réservés au seul 
> destinataire indiqué et peuvent renfermer des renseignements 
> confidentiels et privilégiés. Si vous n'êtes pas le destinataire 
> prévu, toute divulgation, duplication, utilisation ou distribution du 
> courrier ou de toute pièce jointe est interdite. Si vous avez reçu 
> cette communication par erreur, veuillez nous en aviser par courrier 
> et détruire immédiatement le courrier et les pièces jointes. Merci.
> ------------------------------------------------------------------------
>
>
> _______________________________________________
> 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/20160725/6191bfa2/attachment.html>