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

[Tom Rodriguez]

I've got a new version of the GC logging code.  It's now using PrintHeapAtGC routines which will give more useful and better formatted output.  I fixed all the review comments, deleted the EventMarks in GC code since no one objected, renamed _count to _length and _filled to _count in EventLogBase.  Each output line is preceded by Event: to help with greppability.  I've updated the webrev and the examples.

Thanks for all the good feedback.

Here's a sample of the new GC output:

GC Heap History (10):
Event: 9672681252 GC heap before
{Heap before GC invocations=25 (full 12):
 PSYoungGen      total 19712K, used 338K [0xe1e00000, 0xe3400000, 0xf7400000)
  eden space 16896K, 2% used [0xe1e00000,0xe1e54870,0xe2e80000)
  from space 2816K, 0% used [0xe3140000,0xe3140000,0xe3400000)
  to   space 2816K, 0% used [0xe2e80000,0xe2e80000,0xe3140000)
 PSOldGen        total 43008K, used 366K [0xb7400000, 0xb9e00000, 0xe1e00000)
  object space 43008K, 0% used [0xb7400000,0xb745bbf8,0xb9e00000)
 PSPermGen       total 16384K, used 2398K [0xb3400000, 0xb4400000, 0xb7400000)
  object space 16384K, 14% used [0xb3400000,0xb36578e0,0xb4400000)
Event: 9672681255 GC heap after
Heap after GC invocations=25 (full 12):
 PSYoungGen      total 19712K, used 48K [0xe1e00000, 0xe3400000, 0xf7400000)
  eden space 16896K, 0% used [0xe1e00000,0xe1e00000,0xe2e80000)
  from space 2816K, 1% used [0xe2e80000,0xe2e8c000,0xe3140000)
  to   space 2816K, 0% used [0xe3140000,0xe3140000,0xe3400000)
 PSOldGen        total 43008K, used 366K [0xb7400000, 0xb9e00000, 0xe1e00000)
  object space 43008K, 0% used [0xb7400000,0xb745bbf8,0xb9e00000)
 PSPermGen       total 16384K, used 2398K [0xb3400000, 0xb4400000, 0xb7400000)
  object space 16384K, 14% used [0xb3400000,0xb36578e0,0xb4400000)
}

A full example is at http://cr.openjdk.java.net/~never/7141200/example1.log.

tom

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