Request for review 7141200: log some interesting information in ring buffers for crashes

[Tom Rodriguez]

On Jan 31, 2012, at 9:36 AM, Jon Masamitsu wrote:

> Tom,
> 
> I only looked at the files from 
> 
> src/share/vm/services/memoryManager.*
> src/share/vm/utilities/debug.*
> src/share/vm/utilities/events.*
> src/share/vm/utilities/exceptions.cpp
> src/share/vm/utilities/vmError.cpp
> 
> In events.hpp if the variable _filled maybe would be
> better named _entries to indicate the number of entries
> written.  I initially thought with _filled you were trying
> to record the number of times the buffer wrapped.
> 
> Copyrights need updating.
> 
> These are supposed to be start and end times?
> | Time: 0.000000.3 - 0.000000.3

Also what's the opinion on using GCStatInfo instead of something like Universe::print_on.  Jesper had given me code which did both, but I left it out because the two combined seemed like too much output.  Maybe I'm over thinking it though.

tom

> 
> Jon
> 
> 
> On 01/30/12 23: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.
>> 
>> 
>>