CRR (S/M): 7049999: G1: Make the G1PrintHeapRegions output consistent and complete

Wed Jun 22 16:58:54 UTC 2011

Poonam Bajaj wrote:
>>> Will gc in between benchmarks
>>>  G1HR RETIRE 0x6e800000 0x6e87bd98  
>>
>> The stop using the region for allocation so the retire even has the 
>> region's top (in this case: 0x6e87bd98). Note that most regions are 
>> full when retired and we ommit those events (we can easily deduce 
>> those) to reduce the output volume.
> One small question - How do we find the full retired regions ? Do we 
> print a region when it is full ?

A region is retired when another region of the same type is allocated or 
we reach the start or end of a GC (depending on the region). So for Eden 
regions:

1. ALLOC(Eden) Foo
2. ALLOC(Eden) Bar
3. StartGC

At point 2 you know that Foo has just been retired and it was full. At 
point 3 you know that Bar was retired and it was full. If they were not 
full when they were retired, we will have seen a RETIRE event:

1. ALLOC(Eden) Foo
2. RETIRE Foo top
3. ALLOC(Eden) Bar
3. StartGC

Tony

> Thanks,
> Poonam
>
>
> On 6/22/2011 8:48 PM, Tony Printezis wrote:
>> Poonam,
>>
>> Poonam Bajaj wrote:
>>> Hi Tony,
>>>
>>> The new output looks completely different from the earlier output.
>>
>> Indeed. The new output is more concise, more complete, and easier to 
>> parse (and avoids some duplication).
>>
>>> e.g. here's output generated with jdk7-b141:
>>>
>>>  added region to incremental cset (LHS) 0:[0x02c00000, 0x02d00000], 
>>> top 0x02c53040, young YES
>>> new alloc region 1:[0x02d00000,0x02e00000], top 0x02d00000
>>
>> [snip]
>>
>>> It prints the index of the region,
>>
>> We can deduce that from the new output (from the COMMIT events which 
>> are done in order), so it's unnecessary to print it.
>>
>>> and whether it is added to eden or survivor (based on LHS
>>> or RHS).
>>
>> Region allocation events have a region type in the new output too, 
>> like ALLOC(Eden)
>>
>>> The index of the region is missing from the new output. I think it 
>>> would be good
>>> to have it; makes it easier to read the logs.
>>
>> See above.
>>
>>> In the new output, I see events like COMMIT, ALLOC, UNCOMMIT, RETIRE.
>>> Could you please explain these ?
>>> G1HR COMMIT [0x72700000,0x72800000]
>>>   
>>
>> The heap is initialized or expanded and the region is freshly 
>> committed (this was missing from the previous output).
>>
>>>  G1HR ALLOC(Eden) 0x6e800000
>>>   
>>
>> The region just started being used for allocation. In this case it's 
>> an Eden region and allocated to by a mutator thread. ALLOC events are 
>> also generated for regions we allocate to during GC (for Survivor and 
>> Old, depending on the type of region), as well as for humongous regions.
>>
>>> Will gc in between benchmarks
>>>  G1HR RETIRE 0x6e800000 0x6e87bd98
>>>   
>>
>> The stop using the region for allocation so the retire even has the 
>> region's top (in this case: 0x6e87bd98). Note that most regions are 
>> full when retired and we ommit those events (we can easily deduce 
>> those) to reduce the output volume.
>>
>>>  G1HR #StartFullGC 1
>>>  G1HR UNCOMMIT [0x72700000,0x72800000]
>>>   
>>
>> Opposite to COMMIT. The heap got shrunk at the end of a Full GC.
>>
>>> There are some numbers printed between the log entries. What are 
>>> these numbers ?
>>>  G1HR ALLOC(ContinuesH) 0x6f100000 0x6f102010
>>> 3153920                        
>>> <-----                                   
>>> 931067                                          <-----
>>>  G1HR COMMIT [0x6f200000,0x6f300000]
>>>   
>>
>> Output from the benchmark (_201_compress).
>>
>>> For the ALLOC and CSET entries, only one address is printed, looks 
>>> like it is the lower
>>> bound of the region. 
>>
>> Indeed.
>>
>>> It would be good to have both the bounds printed (along with the 
>>> index).
>>
>> This was done to reduce the output volume. Both bounds are only 
>> printed when a region is committed / uncommitted.
>>
>> Tony
>>
>>>  G1HR #StartGC 2
>>>  G1HR CSET 0x6e900000
>>>  G1HR COMMIT [0x6f800000,0x6f900000]
>>>  G1HR ALLOC(Old) 0x6f800000
>>>  G1HR RETIRE 0x6f800000 0x6f826838
>>>
>>>
>>> Thanks,
>>> Poonam
>>>
>>>
>>>
>>> On 6/22/2011 1:04 AM, Tony Printezis wrote:
>>>> Hi,
>>>>
>>>> Could I get a couple of folks to look at this?
>>>>
>>>> http://cr.openjdk.java.net/~tonyp/7049999/webrev.0/
>>>>
>>>> +G1PrintHeapRegions is a very helpful debugging feature that we 
>>>> have used a lot in the past. It'll be very helpful in the long run 
>>>> to ensure that it generates more complete output to save us having 
>>>> to deduce some of it. What was missing in the past was:
>>>>
>>>> * output for humongous region allocations
>>>> * output per region post compaction (as compaction changes the 
>>>> shape of the heap)
>>>> * output when regions are reclaimed during cleanup
>>>>
>>>> Further enhancements include:
>>>>
>>>> * commit / uncommit events
>>>> * trimmed the output to keep the generated log files smaller while 
>>>> not losing any information
>>>> * introduced the G1HRPrinter class and all output goes through it 
>>>> to ensure consistency
>>>>
>>>> I attached an example of the new output.
>>>>
>>>> Tony
>>>>
>>>
>>> -- 
>>> Best regards, Poonam
>>>
>>> Sun, an Oracle company
>>> Sun, an Oracle Company
>>> Poonam Bajaj | Staff Engineer
>>> Phone: +66937451 <tel:+66937451> | Mobile: +9844511366 
>>> <tel:+9844511366>
>>> JVM Sustaining Engineering
>>> | Bangalore
>>> Green Oracle <http://www.oracle.com/commitment> Oracle is committed 
>>> to developing practices and products that help protect the environment
>>>
>
> -- 
> Best regards, Poonam
>
> Sun, an Oracle company
> Sun, an Oracle Company
> Poonam Bajaj | Staff Engineer
> Phone: +66937451 <tel:+66937451> | Mobile: +9844511366 <tel:+9844511366>
> JVM Sustaining Engineering
> | Bangalore
> Green Oracle <http://www.oracle.com/commitment> Oracle is committed to 
> developing practices and products that help protect the environment
>