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

[Tom Rodriguez]

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.

It was that plus a missing conversion to double.  It looks right now.

| GC Index: 1  Type: Minor
| Time: 5.693 - 5.707
| Usage:
|    Pool #0: 1137600 -> 1137600
|    Pool #1: 1040288 -> 0
|    Pool #2: 0 -> 327744
|    Pool #3: 0 -> 0
|    Pool #4: 2292048 -> 2292048


> 
> 
> Trivial typos:
> events.hpp line 108, maybe "Should only be called while mutex is held."
> events.hpp line 58 subclassed rather than subclasses.

Fixed.  Thanks.

tom

> 
> 
> 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.
>> 
>> 
>