PrintSafepointStatistics (was Re: understanding GC logs)

[Darji, Kinnari]

Hi Ramki,
I am running jdk-1.6.0_16 and  Java HotSpot(TM) 64-Bit Server VM (build 14.2-b01, mixed mode). I can't change JDK version.  Is there any other way to have this info printed on GC logs with this JDK version?

Attaching error file..

Thank you
Kinnari

From: Ramki Ramakrishna [mailto:y.s.ramakrishna at oracle.com]
Sent: Wednesday, August 03, 2011 5:48 PM
To: Darji, Kinnari [ICG-IT]
Cc: 'hotspot-gc-use at openjdk.java.net'; hotspot-runtime-dev at openjdk.java.net
Subject: PrintSafepointStatistics (was Re: understanding GC logs)

Hi Kinnari -- hs14, which you are on, is rather old (current dev is hs22;  latest public is hs21).
Is it possible that you could switch to a more recent JDK? If that's not possible,
send me  an hs_err file and I can get a ticket opened for you via the usual support
channels. If the problem occurs with a recent hs21 or hs22, we can certainly
take a look here. In either case, I have modified the subject line for relevance
to the issue at hand, and also cross-posted to hsotspot-runtime-dev at o.j.n<mailto:hsotspot-runtime-dev at o.j.n>
where PrintSafepointStatistics expertise resides.

-- ramki

On 8/3/2011 2:40 PM, Darji, Kinnari wrote:
Hi Ramki,
Not sure what's the problem. The process dies with following when I have +PrintSafepointStatistics

java version "1.6.0_16"
Java(TM) SE Runtime Environment (build 1.6.0_16-b01)
Java HotSpot(TM) 64-Bit Server VM (build 14.2-b01, mixed mode)
     vmop_name               [threads: total initially_running wait_to_block] [time: spin block sync] [vmop_time  time_elapsed] page_trap_count
no vm operation                    [       7          1              1]          [     0     0     0]     [     0        0]          0

Polling page always armed
    0 VM operations coalesced during safepoint
Maximum sync time      0 ms
~

Can you please help?

Thank you
Kinnari

From: Ramki Ramakrishna [mailto:y.s.ramakrishna at oracle.com]
Sent: Wednesday, August 03, 2011 2:36 PM
To: Darji, Kinnari [ICG-IT]
Cc: hotspot-gc-use at openjdk.java.net<mailto:hotspot-gc-use at openjdk.java.net>
Subject: Re: understanding GC logs



On 8/3/2011 11:18 AM, Darji, Kinnari wrote:
Thanks Ramki
So If I look at logs starting [GC and real times, that should be almost application STW time. Am I correct?

yes. Except that the real time in that display has a resolution of 10 ms only.
(Thus the 9.2 ms looked like 0.01 s below, i think.)

But yes, that's the STW time.

One caveat though -- this only lists STW ops attributed to GC.
More generally, you would want to use +PrintSafepointStatistics to
see all STW operations (and details thereof), including of course the
GC ops (which are usually the most common type of STW op, but by
no means the only type).

-- ramki




Thank you
Kinnari

From: Ramki Ramakrishna [mailto:y.s.ramakrishna at oracle.com]
Sent: Wednesday, August 03, 2011 2:08 PM
To: Darji, Kinnari [ICG-IT]
Cc: hotspot-gc-use at openjdk.java.net<mailto:hotspot-gc-use at openjdk.java.net>
Subject: Re: understanding GC logs



On 8/3/2011 10:45 AM, Darji, Kinnari wrote:

Hello GC team,
What does this all different time mean? Can someone please clarify?
What is the time application when application stops?

[GC 9768.668: [ParNew
           ^^^^^^ JVM timestamp (seconds since start of JVM) at start of GC operation)



   3746 Desired survivor size 10878976 bytes, new threshold 4 (max 4)
   3747 - age   1:     594288 bytes,     594288 total
   3748 - age   2:    2369912 bytes,    2964200 total
   3749 - age   3:    2877584 bytes,    5841784 total
   3750 - age   4:    3075264 bytes,    8917048 total
   3751 : 182066K->12384K(191744K), 0.0089120 secs] 2755986K->2586303K(10710272K), 0.0092180 secs]
                                                           ^^^^^^^^                                                            ^^^^^^^
                                                          Duration of Scavenge                                        Duration of whole GC operation
                                                                                                                                      (includes scavenge)



[Times: user=0.09 sys=0.00, real=0.01 secs]
     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Process virtual user and system times, and real (elapsed) time during GC operation.

The time for which the application threads were stopped is about 9.2 ms.

-- ramki
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20110804/db804156/attachment.html 
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: HSError.txt
Url: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20110804/db804156/attachment.txt