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?

I'm using javaTimeNanos() / 1000 which I believe should match the time stamps in GC logs, though it won't necessarily match the timestamps generated by TimeStamp, which is used by tty and LogCompilation.  The Management API use TimeStamp as well.  We have too many different sources, plus relative to JVM begin vs. absolute.  I'm honestly unsure which is truly best here.

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

I think it's a printing bug.  I'm looking into it.

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

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