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

[Christian Thalinger]

On Jan 31, 2012, at 12:01 PM, Christian Thalinger wrote:

> 
> On Jan 31, 2012, at 8:50 AM, 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:
> 
> This looks good.  Since you removed the debug methods to print the events I guess now the way to print them is to call Events::print_all.  Could we have a default outputStream for easier calling in the debugger:
> 
> +   static void print_all(outputStream* out = tty);

Or maybe even just name it Events::print.

-- Chris

> 
> (Although in my experience this doesn't work very good in GDB.)
> 
>> 
>> 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
> 
> Unfortunately these are not there.
> 
> -- Chris
> 
>> 
>> 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.
>> 
>> 
>