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

[Kevin Walls]

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