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

[Stefan Karlsson]

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

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
>