RFR: 8159974: G1 String deduplication logging not aligned with the rest of G1

[Per Liden]

Thanks Stefan.

Per

On 2016-06-30 10:12, Stefan Karlsson wrote:
> Looks good.
>
> StefanK
>
> On 2016-06-27 15:25, Per Liden wrote:
>> Hi,
>>
>> Summary: With the introduction of Unified Logging, the
>> style/conventions used for GC logging was changed in various ways.
>> Some of the logging done by StringDedup was however left using the old
>> style. This patch aligns the dedup logging with the rest of G1.
>>
>> Webrev: http://cr.openjdk.java.net/~pliden/8159974/webrev.0/
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8159974
>>
>> Example, before:
>> ----------------
>> [11.927s][info ][gc,stringdedup] Concurrent String Deduplication
>> 32.3M->32.3M(0.0B), avg 0.0%, 0.7633528 secs
>> [11.927s][debug][gc,stringdedup]    [Last Exec: 0.7633528 secs, Idle:
>> 0.5195570 secs, Blocked: 0/0.0000000 secs]
>> [11.927s][debug][gc,stringdedup]       [Inspected: 1410367]
>> [11.927s][debug][gc,stringdedup]          [Skipped: 0(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Hashed: 1410367(100.0%)]
>> [11.927s][debug][gc,stringdedup]          [Known: 0(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [New: 1410367(100.0%)
>> 32.3M]
>> [11.927s][debug][gc,stringdedup]       [Deduplicated: 0( 0.0%)
>> 0.0B(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Young: 0( 0.0%)      0.0B(
>> 0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Old: 0( 0.0%)      0.0B(
>> 0.0%)]
>> [11.927s][debug][gc,stringdedup]    [Total Exec: 4/6.7536909 secs,
>> Idle: 4/4.1289840 secs, Blocked: 9/0.8971700 secs]
>> [11.927s][debug][gc,stringdedup]       [Inspected: 7163002]
>> [11.927s][debug][gc,stringdedup]          [Skipped: 0(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Hashed: 7159929(100.0%)]
>> [11.927s][debug][gc,stringdedup]          [Known: 2916(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [New: 7160086(100.0%) 163.9M]
>> [11.927s][debug][gc,stringdedup]       [Deduplicated: 177( 0.0%)
>> 5120.0B(  0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Young: 0( 0.0%)      0.0B(
>> 0.0%)]
>> [11.927s][debug][gc,stringdedup]          [Old: 177(100.0%)
>> 5120.0B(100.0%)]
>> [11.927s][debug][gc,stringdedup]    [Table]
>> [11.927s][debug][gc,stringdedup]       [Memory Usage: 250.6M]
>> [11.927s][debug][gc,stringdedup]       [Size: 4194304, Min: 1024, Max:
>> 16777216]
>> [11.927s][debug][gc,stringdedup]       [Entries: 7162825, Load:
>> 170.8%, Cached: 0, Added: 7162825, Removed: 0]
>> [11.927s][debug][gc,stringdedup]       [Resize Count: 12, Shrink
>> Threshold: 2796202(66.7%), Grow Threshold: 8388608(200.0%)]
>> [11.927s][debug][gc,stringdedup]       [Rehash Count: 0, Rehash
>> Threshold: 120, Hash Seed: 0x0]
>> [11.927s][debug][gc,stringdedup]       [Age Threshold: 3]
>> [11.927s][debug][gc,stringdedup]    [Queue]
>> [11.927s][debug][gc,stringdedup]       [Dropped: 0]
>>
>> Example, after:
>> ---------------
>> [11.073s][info ][gc,stringdedup] Concurrent String Deduplication
>> (11.073s)
>> [11.975s][info ][gc,stringdedup] Concurrent String Deduplication
>> 33.2M->33.2M(0.0B) avg 0.0% (11.073s, 11.975s) 901.918ms
>> [11.975s][debug][gc,stringdedup]   Last Exec: 901.918ms, Idle:
>> 407.930ms, Blocked: 0/0.000ms
>> [11.975s][debug][gc,stringdedup]     Inspected:         1450663
>> [11.975s][debug][gc,stringdedup]       Skipped:               0( 0.0%)
>> [11.975s][debug][gc,stringdedup]       Hashed: 1450663(100.0%)
>> [11.975s][debug][gc,stringdedup]       Known:                 0( 0.0%)
>> [11.975s][debug][gc,stringdedup]       New: 1450663(100.0%)     33.2M
>> [11.975s][debug][gc,stringdedup]     Deduplicated:            0( 0.0%)
>>      0.0B(  0.0%)
>> [11.975s][debug][gc,stringdedup]       Young:                 0( 0.0%)
>>      0.0B(  0.0%)
>> [11.975s][debug][gc,stringdedup]       Old:                   0( 0.0%)
>>      0.0B(  0.0%)
>> [11.975s][debug][gc,stringdedup]   Total Exec: 4/7275.988ms, Idle:
>> 4/3620.653ms, Blocked: 8/929.258ms
>> [11.975s][debug][gc,stringdedup]     Inspected:         7348199
>> [11.975s][debug][gc,stringdedup]       Skipped:               0( 0.0%)
>> [11.975s][debug][gc,stringdedup]       Hashed: 7345126(100.0%)
>> [11.975s][debug][gc,stringdedup]       Known:              2916( 0.0%)
>> [11.975s][debug][gc,stringdedup]       New: 7345283(100.0%)    168.1M
>> [11.975s][debug][gc,stringdedup]     Deduplicated:          177( 0.0%)
>>   5120.0B(  0.0%)
>> [11.975s][debug][gc,stringdedup]       Young:                 0( 0.0%)
>>      0.0B(  0.0%)
>> [11.975s][debug][gc,stringdedup]       Old: 177(100.0%)   5120.0B(100.0%)
>> [11.975s][debug][gc,stringdedup]   Table
>> [11.975s][debug][gc,stringdedup]     Memory Usage: 256.2M
>> [11.975s][debug][gc,stringdedup]     Size: 4194304, Min: 1024, Max:
>> 16777216
>> [11.975s][debug][gc,stringdedup]     Entries: 7348022, Load: 175.2%,
>> Cached: 0, Added: 7348022, Removed: 0
>> [11.975s][debug][gc,stringdedup]     Resize Count: 12, Shrink
>> Threshold: 2796202(66.7%), Grow Threshold: 8388608(200.0%)
>> [11.975s][debug][gc,stringdedup]     Rehash Count: 0, Rehash
>> Threshold: 120, Hash Seed: 0x0
>> [11.975s][debug][gc,stringdedup]     Age Threshold: 3
>> [11.975s][debug][gc,stringdedup]   Queue
>> [11.975s][debug][gc,stringdedup]     Dropped: 0
>>
>> cheers,
>> Per
>>
>