RFR: 8027423: Parallel compact GC class unloading measurement includes symbol and string table time

[Jon Masamitsu]

On 3/15/2016 3:18 PM, Stefan Karlsson wrote:
> Hi Jon,
>
> On 15/03/16 22:25, Jon Masamitsu wrote:
>> Stefan,
>>
>> Thanks for this enhancement.
>>
>> http://cr.openjdk.java.net/~stefank/8027423/webrev.00/src/share/vm/gc/g1/g1MarkSweep.cpp.frames.html 
>>
>>
>> The timing for unlink_string_and_symbol_table()
>>
>>> 170 {
>>> 171 GCTraceTime(Debug, gc) t("Scrub String and Symbol Tables", 
>>> gc_timer());
>>>   172     // Delete entries for dead interned string and clean up 
>>> unreferenced symbols in symbol table.
>>>   173 g1h->unlink_string_and_symbol_table(&GenMarkSweep::is_alive);
>>> 174 }
>>
>> will include unlinking of the string Dedup table
>>
>>> 4092   if (G1StringDedup::is_enabled()) {
>>> 4093     G1StringDedup::unlink(is_alive);
>>> 4094   }
>>
>> The other call to G1StringDedup::unlink() in 
>> "share/vm/gc/g1/g1ConcurrentMark.cpp"
>> has its own GCTraceTime
>>
>>> 2127     if (G1StringDedup::is_enabled()) {
>>> 2128       GCTraceTime(Trace, gc) trace("String Deduplication 
>>> Unlink", g1h->gc_timer_cm());
>>> 2129       G1StringDedup::unlink(&g1_is_alive);
>>> 2130     }
>>
>> Why not give the first G1StringDedup::unlink() call its own timer?
>> And bring the
>>
>> GCTraceTime(Debug, gc) t("Scrub String and Symbol Tables", gc_timer());
>>
>> into  unlink_string_and_symbol_table()?
>
> Good point.
>
> If I may, I would like to move the call to G1StringDedup::unlink out 
> of unlink_string_and_symbol_table and into 
> G1MarkSweep::mark_sweep_phase1. That way it will be easier to see what 
> timers we have, and it will be a little bit more similar to 
> G1ConcurrentMark::weakRefsWork.

I like that.

>
> http://cr.openjdk.java.net/~stefank/8027423/webrev.01.delta

Looks good.

Jon

> http://cr.openjdk.java.net/~stefank/8027423/webrev.01
>
> For a future RFE I think we should change the log levels from Trace to 
> Debug and get rid of the GCTraceTimer nesting in 
> G1ConcurrentMark::weakRefsWork.
>
> I also found that ~G1StringSymbolTableUnlinkTask incorrectly logs with 
> the stringdedup tag, so that also have to be a new bug.
>
> Thanks,
> StefanK
>
>>
>>
>> Jon
>>
>>
>> On 3/14/2016 7:22 AM, Stefan Karlsson wrote:
>>> Hi all,
>>>
>>> Please review this patch to get more detailed phase measurements of 
>>> the unloading phases of the parallel and serial collectors. It 
>>> mimics the way CMS reports the unloading phase. G1 parallelizes the 
>>> unloading phase, so it is slightly different.
>>>
>>> http://cr.openjdk.java.net/~stefank/8027423/webrev.00/
>>> https://bugs.openjdk.java.net/browse/JDK-8027423
>>>
>>> Example of the output that you get with -Xlog:gc=debug:
>>> [2.257s][debug][gc] GC(45) Class Unloading (2.256s, 2.257s) 1.669ms
>>> [2.258s][debug][gc] GC(45) Scrub String Table (2.257s, 2.258s) 0.412ms
>>> [2.259s][debug][gc] GC(45) Scrub Symbol Table (2.258s, 2.259s) 1.027ms
>>> [2.292s][info ][gc] GC(45) Pause Full (System.gc()) 80M->2M(98M) 
>>> (2.248s, 2.292s) 44.631ms
>>>
>>> Thanks,
>>> StefanK
>>
>