G1: Interned strings with no references only garbage collected upon full GC.

FULL PRODUCT VERSION :
java version " 1.7.0_21 "
Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)

FULL OS VERSION :
Microsoft Windows [Version 6.1.7601]

A DESCRIPTION OF THE PROBLEM :
When using the G1 garbage collector, interned Strings which are no longer referenced are not garbage collected until heap usage reaches max heap size. As the size of the intern String table grows, heap usage increases and performance of String.intern() degrades considerably.

This was initially observed in a legacy application which executes large numbers of distinct custom sql queries via Hibernate. Hibernate calls String.intern() for each query plan. It only stores references to the n most recently used query plan strings. Dereferenced Strings are not garbage collected until heap usage reaches -Xmx (or a manual " Perform GC " is done via VisualVM). The application previously ran on jrockit where this behaviour was not seen. Likewise, other garbage collectors in JDK7 do not exhibit the same behaviour.

THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Yes

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run the attached test case with " -Xms64m -Xmx1024m -XX:+UseG1GC " and observe the heap usage with VisualVM. Do a comparison without G1 ( " " -Xms64m -Xmx1024m " ) and try different values for -Xms and -Xmx.

EXPECTED VERSUS ACTUAL BEHAVIOR :
TRUNCATED RESULTS WITH DEFAULT GC (java args " ?Xmx384m " ):
Interned 100,000 Strings. Last 100,000 took 172ms. Total time = 0s. Heap Used/Free/Max = 25/219/341mb
Interned 200,000 Strings. Last 100,000 took 509ms. Total time = 0s. Heap Used/Free/Max = 49/194/341mb
Interned 300,000 Strings. Last 100,000 took 521ms. Total time = 1s. Heap Used/Free/Max = 13/231/341mb
Interned 400,000 Strings. Last 100,000 took 249ms. Total time = 1s. Heap Used/Free/Max = 45/199/341mb
Interned 500,000 Strings. Last 100,000 took 487ms. Total time = 1s. Heap Used/Free/Max = 12/232/341mb
Interned 600,000 Strings. Last 100,000 took 316ms. Total time = 2s. Heap Used/Free/Max = 37/207/341mb
Interned 700,000 Strings. Last 100,000 took 632ms. Total time = 2s. Heap Used/Free/Max = 61/182/341mb
Interned 800,000 Strings. Last 100,000 took 227ms. Total time = 3s. Heap Used/Free/Max = 22/222/341mb
Interned 900,000 Strings. Last 100,000 took 318ms. Total time = 3s. Heap Used/Free/Max = 46/198/341mb
Interned 1,000,000 Strings. Last 100,000 took 550ms. Total time = 3s. Heap Used/Free/Max = 7/280/341mb
Interned 1,100,000 Strings. Last 100,000 took 183ms. Total time = 4s. Heap Used/Free/Max = 32/255/341mb
Interned 1,200,000 Strings. Last 100,000 took 415ms. Total time = 4s. Heap Used/Free/Max = 56/230/341mb
Interned 1,300,000 Strings. Last 100,000 took 778ms. Total time = 5s. Heap Used/Free/Max = 82/205/341mb
Interned 1,400,000 Strings. Last 100,000 took 1,382ms. Total time = 6s. Heap Used/Free/Max = 107/180/341mb
Interned 1,500,000 Strings. Last 100,000 took 360ms. Total time = 7s. Heap Used/Free/Max = 24/254/341mb
Interned 1,600,000 Strings. Last 100,000 took 357ms. Total time = 7s. Heap Used/Free/Max = 49/229/341mb
Interned 1,700,000 Strings. Last 100,000 took 930ms. Total time = 8s. Heap Used/Free/Max = 72/205/341mb
Interned 1,800,000 Strings. Last 100,000 took 1,353ms. Total time = 9s. Heap Used/Free/Max = 97/180/341mb
Interned 1,900,000 Strings. Last 100,000 took 903ms. Total time = 10s. Heap Used/Free/Max = 17/268/341mb
Interned 2,000,000 Strings. Last 100,000 took 369ms. Total time = 11s. Heap Used/Free/Max = 42/243/341mb
Interned 2,100,000 Strings. Last 100,000 took 751ms. Total time = 11s. Heap Used/Free/Max = 66/219/341mb
Interned 2,200,000 Strings. Last 100,000 took 1,691ms. Total time = 13s. Heap Used/Free/Max = 91/194/341mb
Interned 2,300,000 Strings. Last 100,000 took 1,773ms. Total time = 15s. Heap Used/Free/Max = 113/171/341mb
Interned 2,400,000 Strings. Last 100,000 took 262ms. Total time = 15s. Heap Used/Free/Max = 26/259/341mb
Interned 2,500,000 Strings. Last 100,000 took 554ms. Total time = 16s. Heap Used/Free/Max = 51/234/341mb
Interned 2,600,000 Strings. Last 100,000 took 1,003ms. Total time = 17s. Heap Used/Free/Max = 76/209/341mb
Interned 2,700,000 Strings. Last 100,000 took 1,472ms. Total time = 18s. Heap Used/Free/Max = 100/184/341mb
Interned 2,800,000 Strings. Last 100,000 took 1,396ms. Total time = 19s. Heap Used/Free/Max = 10/269/341mb
Interned 2,900,000 Strings. Last 100,000 took 245ms. Total time = 20s. Heap Used/Free/Max = 34/245/341mb
Interned 3,000,000 Strings. Last 100,000 took 695ms. Total time = 20s. Heap Used/Free/Max = 60/219/341mb
Interned 3,100,000 Strings. Last 100,000 took 1,233ms. Total time = 22s. Heap Used/Free/Max = 85/195/341mb
Interned 3,200,000 Strings. Last 100,000 took 1,715ms. Total time = 23s. Heap Used/Free/Max = 109/170/341mb
Interned 3,300,000 Strings. Last 100,000 took 426ms. Total time = 24s. Heap Used/Free/Max = 22/253/341mb
Interned 3,400,000 Strings. Last 100,000 took 446ms. Total time = 24s. Heap Used/Free/Max = 48/228/341mb
Interned 3,500,000 Strings. Last 100,000 took 1,001ms. Total time = 25s. Heap Used/Free/Max = 73/202/341mb
Interned 3,600,000 Strings. Last 100,000 took 1,496ms. Total time = 27s. Heap Used/Free/Max = 97/179/341mb
Interned 3,700,000 Strings. Last 100,000 took 989ms. Total time = 28s. Heap Used/Free/Max = 16/257/341mb
Interned 3,800,000 Strings. Last 100,000 took 299ms. Total time = 28s. Heap Used/Free/Max = 40/232/341mb
Interned 3,900,000 Strings. Last 100,000 took 791ms. Total time = 29s. Heap Used/Free/Max = 65/207/341mb
Interned 4,000,000 Strings. Last 100,000 took 1,275ms. Total time = 30s. Heap Used/Free/Max = 88/185/341mb
Interned 4,100,000 Strings. Last 100,000 took 1,256ms. Total time = 31s. Heap Used/Free/Max = 9/262/341mb
Interned 4,200,000 Strings. Last 100,000 took 244ms. Total time = 32s. Heap Used/Free/Max = 35/236/341mb
Interned 4,300,000 Strings. Last 100,000 took 636ms. Total time = 32s. Heap Used/Free/Max = 59/212/341mb
Interned 4,400,000 Strings. Last 100,000 took 1,222ms. Total time = 33s. Heap Used/Free/Max = 84/188/341mb
Interned 4,500,000 Strings. Last 100,000 took 1,574ms. Total time = 35s. Heap Used/Free/Max = 9/257/341mb
Interned 4,600,000 Strings. Last 100,000 took 278ms. Total time = 35s. Heap Used/Free/Max = 32/234/341mb
Interned 4,700,000 Strings. Last 100,000 took 827ms. Total time = 36s. Heap Used/Free/Max = 58/209/341mb
Interned 4,800,000 Strings. Last 100,000 took 1,467ms. Total time = 38s. Heap Used/Free/Max = 81/185/341mb
Interned 4,900,000 Strings. Last 100,000 took 1,476ms. Total time = 39s. Heap Used/Free/Max = 9/257/341mb
Interned 5,000,000 Strings. Last 100,000 took 333ms. Total time = 39s. Heap Used/Free/Max = 33/232/341mb


TRUNCATED RESULTS USING G1 (java args " ?Xmx384m ?XX:+UseG1GC " ):
Interned 100,000 Strings. Last 100,000 took 141ms. Total time = 0s. Heap Used/Free/Max = 24/231/384mb
Interned 200,000 Strings. Last 100,000 took 371ms. Total time = 0s. Heap Used/Free/Max = 49/206/384mb
Interned 300,000 Strings. Last 100,000 took 980ms. Total time = 1s. Heap Used/Free/Max = 46/209/384mb
Interned 400,000 Strings. Last 100,000 took 1,367ms. Total time = 2s. Heap Used/Free/Max = 39/216/384mb
Interned 500,000 Strings. Last 100,000 took 1,964ms. Total time = 4s. Heap Used/Free/Max = 64/191/384mb
Interned 600,000 Strings. Last 100,000 took 2,640ms. Total time = 7s. Heap Used/Free/Max = 59/196/384mb
Interned 700,000 Strings. Last 100,000 took 3,099ms. Total time = 10s. Heap Used/Free/Max = 83/172/384mb
Interned 800,000 Strings. Last 100,000 took 3,807ms. Total time = 14s. Heap Used/Free/Max = 76/179/384mb
Interned 900,000 Strings. Last 100,000 took 4,277ms. Total time = 18s. Heap Used/Free/Max = 101/154/384mb
Interned 1,000,000 Strings. Last 100,000 took 4,916ms. Total time = 23s. Heap Used/Free/Max = 126/129/384mb
Interned 1,100,000 Strings. Last 100,000 took 5,640ms. Total time = 29s. Heap Used/Free/Max = 100/155/384mb
Interned 1,200,000 Strings. Last 100,000 took 5,868ms. Total time = 35s. Heap Used/Free/Max = 125/130/384mb
Interned 1,300,000 Strings. Last 100,000 took 6,386ms. Total time = 41s. Heap Used/Free/Max = 150/105/384mb
Interned 1,400,000 Strings. Last 100,000 took 6,922ms. Total time = 48s. Heap Used/Free/Max = 120/135/384mb
Interned 1,500,000 Strings. Last 100,000 took 7,287ms. Total time = 55s. Heap Used/Free/Max = 146/109/384mb
Interned 1,600,000 Strings. Last 100,000 took 7,892ms. Total time = 63s. Heap Used/Free/Max = 171/84/384mb
Interned 1,700,000 Strings. Last 100,000 took 9,051ms. Total time = 72s. Heap Used/Free/Max = 135/120/384mb
Interned 1,800,000 Strings. Last 100,000 took 9,773ms. Total time = 82s. Heap Used/Free/Max = 161/94/384mb
Interned 1,900,000 Strings. Last 100,000 took 10,527ms. Total time = 92s. Heap Used/Free/Max = 186/69/384mb
Interned 2,000,000 Strings. Last 100,000 took 12,003ms. Total time = 104s. Heap Used/Free/Max = 162/93/384mb
Interned 2,100,000 Strings. Last 100,000 took 12,569ms. Total time = 117s. Heap Used/Free/Max = 187/68/384mb
Interned 2,200,000 Strings. Last 100,000 took 13,650ms. Total time = 131s. Heap Used/Free/Max = 173/82/384mb
Interned 2,300,000 Strings. Last 100,000 took 14,319ms. Total time = 145s. Heap Used/Free/Max = 199/56/384mb
Interned 2,400,000 Strings. Last 100,000 took 15,158ms. Total time = 160s. Heap Used/Free/Max = 194/61/384mb
Interned 2,500,000 Strings. Last 100,000 took 15,381ms. Total time = 175s. Heap Used/Free/Max = 220/35/384mb
Interned 2,600,000 Strings. Last 100,000 took 16,587ms. Total time = 192s. Heap Used/Free/Max = 215/40/384mb
Interned 2,700,000 Strings. Last 100,000 took 17,093ms. Total time = 209s. Heap Used/Free/Max = 211/49/384mb
Interned 2,800,000 Strings. Last 100,000 took 17,929ms. Total time = 227s. Heap Used/Free/Max = 237/23/384mb
Interned 2,900,000 Strings. Last 100,000 took 19,313ms. Total time = 246s. Heap Used/Free/Max = 232/43/384mb
Interned 3,000,000 Strings. Last 100,000 took 19,891ms. Total time = 266s. Heap Used/Free/Max = 258/17/384mb
Interned 3,100,000 Strings. Last 100,000 took 20,940ms. Total time = 287s. Heap Used/Free/Max = 251/41/384mb
Interned 3,200,000 Strings. Last 100,000 took 20,952ms. Total time = 308s. Heap Used/Free/Max = 278/14/384mb
Interned 3,300,000 Strings. Last 100,000 took 21,585ms. Total time = 330s. Heap Used/Free/Max = 268/42/384mb
Interned 3,400,000 Strings. Last 100,000 took 22,304ms. Total time = 352s. Heap Used/Free/Max = 295/15/384mb
Interned 3,500,000 Strings. Last 100,000 took 23,744ms. Total time = 376s. Heap Used/Free/Max = 284/45/384mb
Interned 3,600,000 Strings. Last 100,000 took 24,311ms. Total time = 400s. Heap Used/Free/Max = 311/18/384mb
Interned 3,700,000 Strings. Last 100,000 took 25,638ms. Total time = 426s. Heap Used/Free/Max = 297/53/384mb
Interned 3,800,000 Strings. Last 100,000 took 25,341ms. Total time = 451s. Heap Used/Free/Max = 324/26/384mb
Interned 3,900,000 Strings. Last 100,000 took 26,329ms. Total time = 477s. Heap Used/Free/Max = 307/65/384mb
Interned 4,000,000 Strings. Last 100,000 took 27,501ms. Total time = 505s. Heap Used/Free/Max = 335/37/384mb
Interned 4,100,000 Strings. Last 100,000 took 29,019ms. Total time = 534s. Heap Used/Free/Max = 362/10/384mb
Interned 4,200,000 Strings. Last 100,000 took 12,790ms. Total time = 547s. Heap Used/Free/Max = 8/9/384mb
Interned 4,300,000 Strings. Last 100,000 took 517ms. Total time = 547s. Heap Used/Free/Max = 15/56/384mb
Interned 4,400,000 Strings. Last 100,000 took 1,112ms. Total time = 548s. Heap Used/Free/Max = 40/31/384mb
Interned 4,500,000 Strings. Last 100,000 took 2,034ms. Total time = 550s. Heap Used/Free/Max = 39/95/384mb
Interned 4,600,000 Strings. Last 100,000 took 2,917ms. Total time = 553s. Heap Used/Free/Max = 64/70/384mb
Interned 4,700,000 Strings. Last 100,000 took 3,839ms. Total time = 557s. Heap Used/Free/Max = 89/45/384mb
Interned 4,800,000 Strings. Last 100,000 took 4,859ms. Total time = 562s. Heap Used/Free/Max = 64/70/384mb
Interned 4,900,000 Strings. Last 100,000 took 4,922ms. Total time = 567s. Heap Used/Free/Max = 89/45/384mb
Interned 5,000,000 Strings. Last 100,000 took 6,234ms. Total time = 573s. Heap Used/Free/Max = 76/58/384mb

The corresponding heap graphs from VisualVM are also very useful - please contact me if you would like screenshots.
REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
import java.text.NumberFormat;
import java.util.Locale;

public class StringInternTest {

    public static void main(String[] args) {
        Runtime runtime = Runtime.getRuntime();
        int mb = 1024 * 1024;
        int intervalSize = 100000;
        int maxIntervals = 200;
        long startMillis = System.currentTimeMillis();
        long checkPointMillis = startMillis;

        for (int i = 1; i <= maxIntervals; i++) {
            for (int x = 0; x < intervalSize; x++) {
                String s = System.currentTimeMillis() + " - " + x;
                s.intern();
            }
            long now = System.currentTimeMillis();
            long freeHeap = runtime.freeMemory();
            long totalHeap = runtime.totalMemory();
            long maxHeap = runtime.maxMemory();

            System.out.println(String.format(
                     " Interned %s Strings. Last %s took %sms. Total time = %ss. Heap Used/Free/Max = %d/%d/%dmb " ,
                    formatNumber(i * intervalSize),
                    formatNumber(intervalSize),
                    formatNumber(now - checkPointMillis),
                    formatNumber((now - startMillis) / 1000),
                    (totalHeap - freeHeap) / mb,
                    freeHeap / mb,
                    maxHeap / mb)
                    );
            checkPointMillis = now;
        }
    }

    private static String formatNumber(long num) {
        return NumberFormat.getNumberInstance(Locale.UK).format(num);
    }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
Connect via VisualVM and press the " Perform GC " button.