RFR: 8159974: G1 String deduplication logging not aligned with the rest of G1
kirk.pepperdine at gmail.com
kirk.pepperdine at gmail.com
Mon Jun 27 13:35:30 UTC 2016
Hi Per,
What is the difference between these two lines…
> [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
Is it possible to stack the following information so that you are doing 1 write instead of many?
> [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%)
to something like
[11.975s][debug][gc,stringdedup] Inspected: 1450663 Skipped: 0( 0.0%) Hashed: 1450663(100.0%) Known: 0( 0.0%) New: 1450663(100.0%) 33.2M Deduplicated: 0( 0.0%) 0.0B( 0.0%) Young: 0( 0.0%) 0.0B( 0.0%) Old: 0( 0.0%) 0.0B( 0.0%)
Kind regards,
Kirk Pepperdine
> On Jun 27, 2016, at 3:25 PM, Per Liden <per.liden at oracle.com> 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
>
More information about the hotspot-gc-dev
mailing list