-
Bug
-
Resolution: Fixed
-
P3
-
17, 18
-
b26
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-8278376 | 17.0.3-oracle | Aleksey Shipilev | P3 | Resolved | Fixed | b01 |
JDK-8278100 | 17.0.2 | Aleksey Shipilev | P3 | Resolved | Fixed | b08 |
Reported here: https://twitter.com/nickebbitt/status/1465617649547849733
Seems to reproduce with Shenandoah, but it is actually a generic bug in string dedup code.
$ cat TestLotsaStrings.java
import java.util.Random;
public class TestLotsaStrings {
static int counter = 1_000_000_000;
private static String newString() {
counter++;
if (counter >= 2_000_000_000) counter = 1_000_000_000;
return "str" + counter;
}
static Random r = new Random();
static String[] strings = new String[1024*1024];
static volatile Object sink;
public static void main(String... args) {
for (int c = 0; c < strings.length; c++) {
strings[c] = newString();
}
while (true) {
for (int c = 0; c < 100; c++) {
int i = r.nextInt(strings.length);
strings[i] = newString();
}
for (int c = 0; c < 1024; c++) {
sink = new byte[64*1024];
}
}
}
}
$ build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+UseShenandoahGC -XX:+UseStringDeduplication -XX:NativeMemoryTracking=summary -Xmx1g -Xlog:gc TestLotsaStrings
...
$ while true; do jcmd $pid VM.native_memory summary | grep "Total:"; sleep 1; done
...
Total: reserved=2556143KB, committed=1178839KB
Total: reserved=2556348KB, committed=1179044KB
Total: reserved=2556520KB, committed=1179216KB
Total: reserved=2556727KB, committed=1179423KB
Total: reserved=2556947KB, committed=1179643KB
Total: reserved=2557110KB, committed=1179806KB
$ while true; do jcmd $pid VM.native_memory summary | grep "String Dedup"; sleep 1; done
- String Deduplication (reserved=36860KB, committed=36860KB)
- String Deduplication (reserved=37021KB, committed=37021KB)
- String Deduplication (reserved=37236KB, committed=37236KB)
- String Deduplication (reserved=37401KB, committed=37401KB)
- String Deduplication (reserved=37620KB, committed=37620KB)
- String Deduplication (reserved=37785KB, committed=37785KB)
Seems to leak about 200 KB/sec in string dedup storage. Bisection points toJDK-8254598 as the starting point. Before that change, the "Total" was very stable.
Adding more cleanup logs reveals that StringDedup::Config::should_cleanup_table always returns "false", because _dead_factor_for_cleanup is 5.0, and dead_count is always smaller than entry_count * _dead_factor_for_cleanup!
[17.188s][debug][stringdedup] Table: 1152775 values in 96001 buckets, 104004 dead (0)
[17.188s][debug][stringdedup] Cleanup: dead_count 104004
[17.188s][debug][stringdedup] Cleanup: entry_count 1152775
[17.188s][debug][stringdedup] Cleanup: _minimum_dead_for_cleanup 100
[17.188s][debug][stringdedup] Cleanup: _dead_factor_for_cleanup 5.000000
[17.188s][debug][stringdedup] Cleanup: (dead_count > _minimum_dead_for_cleanup) = true
[17.188s][debug][stringdedup] Cleanup: (dead_count > (entry_count * _dead_factor_for_cleanup) = false
Because here:
void StringDedup::Config::initialize() {
...
_dead_factor_for_cleanup = percent_of(StringDeduplicationCleanupDeadPercent, 100);
...
}
...where:
// Returns numerator/denominator as percentage value from 0 to 100. If denominator
// is zero, return 0.0.
template<typename T>
inline double percent_of(T numerator, T denominator) {
return denominator != 0 ? (double)numerator / denominator * 100.0 : 0.0;
}
So converting StringDeduplicationCleanupDeadPercent (default is 5) to "factor" yields the same 5.0.
Which means the table is never cleaned up by that trigger.
After a simple fix (see PR), the table is finally cleaned up in this test:
; lots of dead
[183.057s][debug][stringdedup] Table: 1103660 values in 96001 buckets, 56064 dead (0)
; finally triggers
[183.231s][debug][stringdedup] Cleanup: dead_count 56063
[183.231s][debug][stringdedup] Cleanup: entry_count 1104658
[183.231s][debug][stringdedup] Cleanup: _minimum_dead_for_cleanup 100
[183.231s][debug][stringdedup] Cleanup: _dead_factor_for_cleanup 0.050000
[183.231s][debug][stringdedup] Cleanup: (dead_count > _minimum_dead_for_cleanup) = true
[183.231s][debug][stringdedup] Cleanup: (dead_count > (entry_count * _dead_factor_for_cleanup) = true
[183.231s][debug][stringdedup] Cleanup: should cleanup
[183.231s][debug][stringdedup] Cleanup started
[183.355s][info ][stringdedup] Concurrent String Deduplication 998/31936.0B (new), 0/0.0B (deduped), avg 0.0%, 1.147ms of 125.556ms
[183.355s][debug][stringdedup] Last Process: 1/1.147ms, Idle: 1/173.195ms, Blocked: 2/3.639ms
[183.355s][debug][stringdedup] Last Cleanup Table: 1/120.706ms
[183.356s][debug][stringdedup] Inspected: 998
[183.356s][debug][stringdedup] Known: 0( 0.0%)
[183.356s][debug][stringdedup] Shared: 0( 0.0%)
[183.356s][debug][stringdedup] New: 998(100.0%) 31936.0B
[183.356s][debug][stringdedup] Replaced: 0( 0.0%)
[183.356s][debug][stringdedup] Deleted: 56063(5617.5%)
[183.356s][debug][stringdedup] Deduplicated: 0( 0.0%) 0.0B( 0.0%)
[183.356s][debug][stringdedup] Skipped: 0 (dead), 0 (incomplete), 0 (shared)
[183.356s][debug][stringdedup] Total Process: 1105/5734.652ms, Idle: 1105/174234.419ms, Blocked: 74/113.146ms
[183.356s][debug][stringdedup] Total Resize Table: 3/202.247ms
[183.356s][debug][stringdedup] Total Cleanup Table: 20/2623.522ms
[183.356s][debug][stringdedup] Inspected: 2164403
[183.356s][debug][stringdedup] Known: 1821( 0.1%)
[183.356s][debug][stringdedup] Shared: 0( 0.0%)
[183.356s][debug][stringdedup] New: 2162582( 99.9%) 67598.9K
[183.356s][debug][stringdedup] Replaced: 0( 0.0%)
[183.356s][debug][stringdedup] Deleted: 1113987( 51.5%)
[183.356s][debug][stringdedup] Deduplicated: 44( 0.0%) 1320.0B( 0.0%)
[183.356s][debug][stringdedup] Skipped: 2908 (dead), 0 (incomplete), 0 (shared)
; woot, squeaky clean
[183.356s][debug][stringdedup] Table: 1048595 values in 96001 buckets, 0 dead (2)
Seems to reproduce with Shenandoah, but it is actually a generic bug in string dedup code.
$ cat TestLotsaStrings.java
import java.util.Random;
public class TestLotsaStrings {
static int counter = 1_000_000_000;
private static String newString() {
counter++;
if (counter >= 2_000_000_000) counter = 1_000_000_000;
return "str" + counter;
}
static Random r = new Random();
static String[] strings = new String[1024*1024];
static volatile Object sink;
public static void main(String... args) {
for (int c = 0; c < strings.length; c++) {
strings[c] = newString();
}
while (true) {
for (int c = 0; c < 100; c++) {
int i = r.nextInt(strings.length);
strings[i] = newString();
}
for (int c = 0; c < 1024; c++) {
sink = new byte[64*1024];
}
}
}
}
$ build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+UseShenandoahGC -XX:+UseStringDeduplication -XX:NativeMemoryTracking=summary -Xmx1g -Xlog:gc TestLotsaStrings
...
$ while true; do jcmd $pid VM.native_memory summary | grep "Total:"; sleep 1; done
...
Total: reserved=2556143KB, committed=1178839KB
Total: reserved=2556348KB, committed=1179044KB
Total: reserved=2556520KB, committed=1179216KB
Total: reserved=2556727KB, committed=1179423KB
Total: reserved=2556947KB, committed=1179643KB
Total: reserved=2557110KB, committed=1179806KB
$ while true; do jcmd $pid VM.native_memory summary | grep "String Dedup"; sleep 1; done
- String Deduplication (reserved=36860KB, committed=36860KB)
- String Deduplication (reserved=37021KB, committed=37021KB)
- String Deduplication (reserved=37236KB, committed=37236KB)
- String Deduplication (reserved=37401KB, committed=37401KB)
- String Deduplication (reserved=37620KB, committed=37620KB)
- String Deduplication (reserved=37785KB, committed=37785KB)
Seems to leak about 200 KB/sec in string dedup storage. Bisection points to
Adding more cleanup logs reveals that StringDedup::Config::should_cleanup_table always returns "false", because _dead_factor_for_cleanup is 5.0, and dead_count is always smaller than entry_count * _dead_factor_for_cleanup!
[17.188s][debug][stringdedup] Table: 1152775 values in 96001 buckets, 104004 dead (0)
[17.188s][debug][stringdedup] Cleanup: dead_count 104004
[17.188s][debug][stringdedup] Cleanup: entry_count 1152775
[17.188s][debug][stringdedup] Cleanup: _minimum_dead_for_cleanup 100
[17.188s][debug][stringdedup] Cleanup: _dead_factor_for_cleanup 5.000000
[17.188s][debug][stringdedup] Cleanup: (dead_count > _minimum_dead_for_cleanup) = true
[17.188s][debug][stringdedup] Cleanup: (dead_count > (entry_count * _dead_factor_for_cleanup) = false
Because here:
void StringDedup::Config::initialize() {
...
_dead_factor_for_cleanup = percent_of(StringDeduplicationCleanupDeadPercent, 100);
...
}
...where:
// Returns numerator/denominator as percentage value from 0 to 100. If denominator
// is zero, return 0.0.
template<typename T>
inline double percent_of(T numerator, T denominator) {
return denominator != 0 ? (double)numerator / denominator * 100.0 : 0.0;
}
So converting StringDeduplicationCleanupDeadPercent (default is 5) to "factor" yields the same 5.0.
Which means the table is never cleaned up by that trigger.
After a simple fix (see PR), the table is finally cleaned up in this test:
; lots of dead
[183.057s][debug][stringdedup] Table: 1103660 values in 96001 buckets, 56064 dead (0)
; finally triggers
[183.231s][debug][stringdedup] Cleanup: dead_count 56063
[183.231s][debug][stringdedup] Cleanup: entry_count 1104658
[183.231s][debug][stringdedup] Cleanup: _minimum_dead_for_cleanup 100
[183.231s][debug][stringdedup] Cleanup: _dead_factor_for_cleanup 0.050000
[183.231s][debug][stringdedup] Cleanup: (dead_count > _minimum_dead_for_cleanup) = true
[183.231s][debug][stringdedup] Cleanup: (dead_count > (entry_count * _dead_factor_for_cleanup) = true
[183.231s][debug][stringdedup] Cleanup: should cleanup
[183.231s][debug][stringdedup] Cleanup started
[183.355s][info ][stringdedup] Concurrent String Deduplication 998/31936.0B (new), 0/0.0B (deduped), avg 0.0%, 1.147ms of 125.556ms
[183.355s][debug][stringdedup] Last Process: 1/1.147ms, Idle: 1/173.195ms, Blocked: 2/3.639ms
[183.355s][debug][stringdedup] Last Cleanup Table: 1/120.706ms
[183.356s][debug][stringdedup] Inspected: 998
[183.356s][debug][stringdedup] Known: 0( 0.0%)
[183.356s][debug][stringdedup] Shared: 0( 0.0%)
[183.356s][debug][stringdedup] New: 998(100.0%) 31936.0B
[183.356s][debug][stringdedup] Replaced: 0( 0.0%)
[183.356s][debug][stringdedup] Deleted: 56063(5617.5%)
[183.356s][debug][stringdedup] Deduplicated: 0( 0.0%) 0.0B( 0.0%)
[183.356s][debug][stringdedup] Skipped: 0 (dead), 0 (incomplete), 0 (shared)
[183.356s][debug][stringdedup] Total Process: 1105/5734.652ms, Idle: 1105/174234.419ms, Blocked: 74/113.146ms
[183.356s][debug][stringdedup] Total Resize Table: 3/202.247ms
[183.356s][debug][stringdedup] Total Cleanup Table: 20/2623.522ms
[183.356s][debug][stringdedup] Inspected: 2164403
[183.356s][debug][stringdedup] Known: 1821( 0.1%)
[183.356s][debug][stringdedup] Shared: 0( 0.0%)
[183.356s][debug][stringdedup] New: 2162582( 99.9%) 67598.9K
[183.356s][debug][stringdedup] Replaced: 0( 0.0%)
[183.356s][debug][stringdedup] Deleted: 1113987( 51.5%)
[183.356s][debug][stringdedup] Deduplicated: 44( 0.0%) 1320.0B( 0.0%)
[183.356s][debug][stringdedup] Skipped: 2908 (dead), 0 (incomplete), 0 (shared)
; woot, squeaky clean
[183.356s][debug][stringdedup] Table: 1048595 values in 96001 buckets, 0 dead (2)
- backported by
-
JDK-8278100 String Deduplication table is never cleaned up due to bad dead_factor_for_cleanup
-
- Resolved
-
-
JDK-8278376 String Deduplication table is never cleaned up due to bad dead_factor_for_cleanup
-
- Resolved
-
- relates to
-
JDK-8254598 StringDedupTable should use OopStorage
-
- Resolved
-
- links to
-
Commit openjdk/jdk17u/a6c3b5de
-
Commit openjdk/jdk/8d7958e4
-
Review openjdk/jdk17u/316
-
Review openjdk/jdk/6613
(2 links to)