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

[Stefan Karlsson]

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
>