Request for review 7141200: log some interesting information in ring buffers for crashes
Bengt Rutisson
bengt.rutisson at oracle.com
Wed Feb 1 00:50:18 PST 2012
Tom,
Thanks for changing this! It looks much better. The code is cleaner and
the the information in the hs_err file is more useful.
I have only looked through the GC code changes. I think it looks good.
Some comments:
The information provided by print_heap_after_gc() is very good, but it
does not clearly communicate what type of GC it was. In particular for
G1 I think it would be interesting to know if it was a young GC, mixed
GC, initial mark of full GC. I'm ok with not including this information
now, but maybe we can file a bug to include it? Or maybe we should just
leave it for when we re-work this based on JFR...
G1 has the notion of "extended" heap information. This can be turned on
with the flag PrintHeapAtGCExtended. This gives a lot of information for
each region in the heap. I tried running with your patch and turning
this flag on. Fortunately you limit the length of the events so the
hs_err file is not as huge as it could be. But it gets quite difficult
to parse the hs_err file since the extended information kind of messes
the output up. I'm attaching an example hs_err file with this output.
Again, I'm ok with leaving this as it is and just filing a bug that we
should try to turn off "extended" when we log the information for the
event buffer. I don't expect that PrintHeapAtGCExtended will be widely
used by customers.
Code comments:
psMarkSweep.cpp, psParallelCompact.cpp, psScavenge.cpp and collectedHeap.hpp
If you change the calls "CollectedHeap::print_heap_before_gc()" to
"heap->print_heap_before_gc()" the print_heap_before_gc() method does
not have to be static. That also means that the _gc_heap_log does not
have to be static. Instead we could always set it up in the
CollectedHeap::CollectedHeap() constructor as.
if (LogEvents) {
_gc_heap_log = new GCHeapLog();
} else {
_gc_heap_log = NULL;
}
No need for collectedHeap_log_init() and initialize_heap_log() anymore.
collectedHeap.cpp
void GCHeapLog::log_heap(bool before) {
if (!should_log()) return;
The GC code tries to standardize on always using {} after if. So, it
would be nice if this was:
void GCHeapLog::log_heap(bool before) {
if (!should_log()) {
return;
}
Overall this looks great. Thanks again for fixing all of this!
Bengt
On 2012-01-31 23:27, Tom Rodriguez wrote:
> I've got a new version of the GC logging code. It's now using PrintHeapAtGC routines which will give more useful and better formatted output. I fixed all the review comments, deleted the EventMarks in GC code since no one objected, renamed _count to _length and _filled to _count in EventLogBase. Each output line is preceded by Event: to help with greppability. I've updated the webrev and the examples.
>
> Thanks for all the good feedback.
>
> Here's a sample of the new GC output:
>
> GC Heap History (10):
> Event: 9672681252 GC heap before
> {Heap before GC invocations=25 (full 12):
> PSYoungGen total 19712K, used 338K [0xe1e00000, 0xe3400000, 0xf7400000)
> eden space 16896K, 2% used [0xe1e00000,0xe1e54870,0xe2e80000)
> from space 2816K, 0% used [0xe3140000,0xe3140000,0xe3400000)
> to space 2816K, 0% used [0xe2e80000,0xe2e80000,0xe3140000)
> PSOldGen total 43008K, used 366K [0xb7400000, 0xb9e00000, 0xe1e00000)
> object space 43008K, 0% used [0xb7400000,0xb745bbf8,0xb9e00000)
> PSPermGen total 16384K, used 2398K [0xb3400000, 0xb4400000, 0xb7400000)
> object space 16384K, 14% used [0xb3400000,0xb36578e0,0xb4400000)
> Event: 9672681255 GC heap after
> Heap after GC invocations=25 (full 12):
> PSYoungGen total 19712K, used 48K [0xe1e00000, 0xe3400000, 0xf7400000)
> eden space 16896K, 0% used [0xe1e00000,0xe1e00000,0xe2e80000)
> from space 2816K, 1% used [0xe2e80000,0xe2e8c000,0xe3140000)
> to space 2816K, 0% used [0xe3140000,0xe3140000,0xe3400000)
> PSOldGen total 43008K, used 366K [0xb7400000, 0xb9e00000, 0xe1e00000)
> object space 43008K, 0% used [0xb7400000,0xb745bbf8,0xb9e00000)
> PSPermGen total 16384K, used 2398K [0xb3400000, 0xb4400000, 0xb7400000)
> object space 16384K, 14% used [0xb3400000,0xb36578e0,0xb4400000)
> }
>
> A full example is at http://cr.openjdk.java.net/~never/7141200/example1.log.
>
> tom
>
> On Jan 31, 2012, at 10:08 AM, Kevin Walls wrote:
>
>> Hi Tom,
>>
>> Thanks for the examples.
>>
>> Really like that we have a timestamp so we can see the ordering of separate types
>> of events. But we will get questions on how to convert a big number like
>> 9617182121 into a time, and how it relates to times we see in other log files:
>> can we convert it, e.g the same format as the GC logs?
>>
>> (worst case, I was thinking we log the value of first_hrtime so we have some baseline,
>> but I'm sure we can make it prettier than that 8-) )
>>
>>
>> Why are the GC events all happening in the time period: Time: 0.000000.3 - 0.000000.3
>>
>> That must be the format string %f.3 in memoryManager.cpp. Again maybe we
>> can make this more readable, this figure will no doubt be used to search GC logs.
>>
>>
>> Trivial typos:
>> events.hpp line 108, maybe "Should only be called while mutex is held."
>> events.hpp line 58 subclassed rather than subclasses.
>>
>>
>> Thanks!
>> Kevin
>>
>>
>> On 31/01/12 07:50, Tom Rodriguez wrote:
>>> http://cr.openjdk.java.net/~never/7141200
>>> 664 lines changed: 389 ins; 185 del; 90 mod; 37188 unchg
>>>
>>> 7141200: log some interesting information in ring buffers for crashes
>>> Reviewed-by:
>>>
>>> As part of convergence with JRockit it was requested that Hotspot
>>> capture some internal events in ring buffer so that they could be
>>> dumped into the error log to provide more context at crash time. I
>>> chose to make these logs be mostly text based for simplicity of
>>> implementation. Eventually more of the flight recorder infrastructure
>>> will be in place and the recording of this kind of data should be more
>>> integrated the infrastructure for that. So my current implementation
>>> is somewhat ad hoc since I expect it will be revisited.
>>>
>>> This also doesn't include one of the more important features, dumping
>>> crashing context when scanning the heap. Capturing that information
>>> without impacting GC performance is difficult and would require broad
>>> changes in the heap iteration code. That can possibly be address later.
>>>
>>> I've chosen to tear out the existing Events class which was a debug
>>> only feature of limited use and extend that into a collection of
>>> product ring buffers. They are registered during JVM startup and
>>> dumped into the hs_err log when the JVM crashes. There are a couple
>>> different categories maintained: compilation, deopt, internal
>>> exceptions, other uncategorized messages and GC events. Each ring
>>> buffer has it's own mutex to reduce contention across different kinds
>>> of events and generally logging is performed for relatively infrequent
>>> or expensive events to minimize any performance penalty. I also chose
>>> to maintain separate logs for the categories so that higher frequency
>>> events one kind don't hide other kinds.
>>>
>>> I eliminated some of the less useful Events::log calls as well and
>>> move some others around.
>>>
>>> The GC logging keeps track of GC history using GCStatInfos. This has
>>> the benefit that it's GC independent and provides before and after
>>> information. It could also or instead capture Universe::print_on
>>> though that's pretty verbose output. The GC section is fairly long
>>> and I'm not sure what the best output would be. Opinions would be
>>> appreciated.
>>>
>>> There are some EventMarks in GC code that I'm tempted to delete. Any
>>> objections?
>>>
>>> I put a couple example logs at:
>>>
>>> http://cr.openjdk.java.net/~never/7141200/example1.log
>>> http://cr.openjdk.java.net/~never/7141200/example2.log
>>>
>>> I can produce others if needed.
>>>
>>> Performance seems to be largely unchanged according to refworkload but
>>> I'm still running some benchmarks. Tested with JCK vm and lang, and
>>> the nsk tests.
>>>
>>>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: hs_err_pid4492.log
Url: http://mail.openjdk.java.net/pipermail/hotspot-dev/attachments/20120201/6d36df85/hs_err_pid4492-0001.log
More information about the hotspot-dev
mailing list