String Deduplication table is never cleaned up due to bad dead_factor_for_cleanup

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 to JDK-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)