RFR: 8159974: G1 String deduplication logging not aligned with the rest of G1
Per Liden
per.liden at oracle.com
Tue Jun 28 07:46:19 UTC 2016
Hi Kirk,
On 2016-06-27 15:35, kirk.pepperdine at gmail.com wrote:
> 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
The first line indicates the start of the concurrent phase, the second
the end of the concurrent phase. There could be all kinds of things
happening in between, like GCs, etc. This follows the style used by
other concurrent phases, such as concurrent mark.
> 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%)
I have mixed feelings about this. While something like this would make
the output more compact, it this also tends to hurt readability.
In any case, given the FC-state of JDK9 I'm not so keen on letting this
change grow to fixing things other than the obvious style differences.
cheers,
Per
>
> 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