[prev in list] [next in list] [prev in thread] [next in thread]
List: openjdk-hotspot-gc-use
Subject: GC Time by cause/phase
From: Chris Conroy <cconroy () squareup ! com>
Date: 2013-10-28 20:20:28
Message-ID: CA+=gZKARsHhppu4-pDbt0QU9hJij+kuhs1vndJrEy03TJDxRrw () mail ! gmail ! com
[Download RAW message or body]
[Attachment #2 (multipart/alternative)]
(I tried sending this to hotspot-dev 5 days ago but it still has not been
approved by the moderator. Perhaps this is the more appropriate list?)
I'm trying to get detailed GC timing metrics. In particular, I'm interested
in tracking time spent in stop the world GC vs parallel GC in my
application. I was hoping that the GarbageCollectionNotificationInfo would
give me what I need, but I'm having some trouble. I can get total wallclock
time per collector by polling the Garbage Collector MX Beans or watching
the corresponding notifications. However, I'd like to be able to record
time spent in the different phases within the collector (e.g. rescan
stop-the-world vs. concurrent sweep)
I see that recently GC Cause tracing was fixed for CMS in hotspot (
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=8008500).
I tried testing jdk7u45 to see if I could get the corresponding cause
information in the GarbageCollectionNotificationInfo MBean notification.
Confusingly, the cause for CMS runs reported via this notification are
always "No GC" even though running the same code with -XX:+PrintGCDetails
shows me the various CMS phases like Initial Mark or Concurrent Mark.
I'm not familiar with the hotspot code base, but it would seem that the
cause should propagate up through gcNotifier.cpp and into this
notification, but there is definitely a disconnect between the verbose GC
logs and the notifications I get.
It doesn't look like jstat or any of the other standard tools give this
information, but it would be really valuable to understand how much time
we've been completely stopped vs. doing parallel GC as the former has
important implications for an application trying to service requests on a
tight deadline.
Is this a bug in what hotspot sends to GarbageCollectionNotificationInfo?
Is there some other programmatic way of getting this information, or do I
just need to tail and parse the JVM GC Logs?
[Attachment #5 (text/html)]
<div dir="ltr"><div style="font-family:arial,sans-serif;font-size:13px">(I tried \
sending this to hotspot-dev 5 days ago but it still has not been approved by the \
moderator. Perhaps this is the more appropriate list?)</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div \
style="font-family:arial,sans-serif;font-size:13px">I'm trying to get detailed GC \
timing metrics. In particular, I'm interested in tracking time spent in stop the \
world GC vs parallel GC in my application. I was hoping that the \
GarbageCollectionNotificationInfo would give me what I need, but I'm having some \
trouble. I can get total wallclock time per collector by polling the Garbage \
Collector MX Beans or watching the corresponding notifications. However, I'd like \
to be able to record time spent in the different phases within the collector (e.g. \
rescan stop-the-world vs. concurrent sweep)</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><span \
style="font-family:arial,sans-serif;font-size:13px">I see that recently GC Cause \
tracing was fixed for CMS in hotspot (</span><a \
href="http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=8008500" target="_blank" \
style="font-family:arial,sans-serif;font-size:13px">http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=8008500</a><span \
style="font-family:arial,sans-serif;font-size:13px">).</span><div \
style="font-family:arial,sans-serif;font-size:13px">
<br></div><div style="font-family:arial,sans-serif;font-size:13px">I tried testing \
jdk7u45 to see if I could get the corresponding cause information in the \
GarbageCollectionNotificationInfo MBean notification. Confusingly, the cause for CMS \
runs reported via this notification are always "No GC" even though running \
the same code with -XX:+PrintGCDetails shows me the various CMS phases like Initial \
Mark or Concurrent Mark.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div \
style="font-family:arial,sans-serif;font-size:13px">I'm not familiar with the \
hotspot code base, but it would seem that the cause should propagate up through \
gcNotifier.cpp and into this notification, but there is definitely a disconnect \
between the verbose GC logs and the notifications I get.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div \
style="font-family:arial,sans-serif;font-size:13px">It doesn't look like jstat or \
any of the other standard tools give this information, but it would be really \
valuable to understand how much time we've been completely stopped vs. doing \
parallel GC as the former has important implications for an application trying to \
service requests on a tight deadline.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div \
style="font-family:arial,sans-serif;font-size:13px">Is this a bug in what hotspot \
sends to GarbageCollectionNotificationInfo? Is there some other programmatic way of \
getting this information, or do I just need to tail and parse the JVM GC Logs?</div>
</div>
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic