Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8277981

String Deduplication table is never cleaned up due to bad dead_factor_for_cleanup

    XMLWordPrintable

    Details

    • Subcomponent:
      gc
    • Resolved In Build:
      b26

      Backports

        Description

        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)

          Attachments

            Issue Links

              Activity

                People

                Assignee:
                shade Aleksey Shipilev
                Reporter:
                shade Aleksey Shipilev
                Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                  Dates

                  Created:
                  Updated:
                  Resolved: