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

[Mikael Gerdin]

Hi,

On 2016-03-15 23:18, 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.
>
> http://cr.openjdk.java.net/~stefank/8027423/webrev.01.delta
> http://cr.openjdk.java.net/~stefank/8027423/webrev.01

Looks good.
/Mikael

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