PrintSafepointStatistics (was Re: understanding GC logs)

Y. S. Ramakrishna y.s.ramakrishna at oracle.com
Thu Aug 4 10:12:20 PDT 2011


Hi Kinnari --

On 08/04/11 08:01, Darji, Kinnari wrote:
> 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?

I'll get you in touch, off-list, with support folk so they can help open a service
ticket based on your support contract for the older JDK.

As regards having this kind of info printed without recourse to +PrintSafepointStatistics,
try -XX:+PrintGCApplicationStoppedTime and -XX:+PrintGCApplicationConcurrentTime,
which should give you the times you want, albeit with none of the finer
details that +PrintSafepointStatistics would have provided you.
Here's a description of those flags from globals.hpp:-

   product(bool, PrintGCApplicationConcurrentTime, false,                    \
           "Print the time the application has been running")                \
                                                                             \
   product(bool, PrintGCApplicationStoppedTime, false,                       \
           "Print the time the application has been stopped")                \
                                                                             \
(... basically between safepoints, or at safepoints respectively).

As regards:

> 
>  
> 
> Attaching error file..

As I understood you were getting a JVM crash when you used
+PrintSafepointStatistics with 6u16. In that case, the JVM would
typically dump a file named hs_err_<pid>.log in the $CWD of
your invoking shell. That's what the support folks would
want (along with the core file may be in some cases).

Please send the hs_err_*.log file so I can provide
that to the support folk.

It is possible that someone on the runtime list
might already recognize this problem as one that
has since been fixed.

-- ramki

> 
>  
> 
> 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
> 
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use


More information about the hotspot-gc-dev mailing list