Java's String Garbage Collection: Or Why Is This Consuming So Much Memory

Solved

I'm trying to understand why one of my unit tests is consuming so much memory. The first thing I did was run just that one test and measure with VisualVM:

The initial flat line is due to a Thread.sleep() at the start of the test to give VisualVM time to start up.

The test (and setup method) are quite simple:

@BeforeClass
private void setup() throws Exception {
    mockedDatawireConfig = mock(DatawireConfig.class);
    when(mockedDatawireConfig.getUrl()).thenReturn(new URL("http://example.domain.fake/"));
    when(mockedDatawireConfig.getTid()).thenReturn("0000000");
    when(mockedDatawireConfig.getMid()).thenReturn("0000000");
    when(mockedDatawireConfig.getDid()).thenReturn("0000000");
    when(mockedDatawireConfig.getAppName()).thenReturn("XXXXXXXXXXXXXXX");
    when(mockedDatawireConfig.getNodeId()).thenReturn("t");

    mockedVersionConfig = mock(VersionConfig.class);
    when(mockedVersionConfig.getDatawireVersion()).thenReturn("000031");

    defaultCRM = new ClientRefManager();
    defaultCRM.setVersionConfig(mockedVersionConfig);
    defaultCRM.setDatawireConfig(mockedDatawireConfig);
}

@Test
public void transactionCounterTest() throws Exception {
    Thread.sleep(15000L);
    String appInstanceID = "";
    for (Long i = 0L; i < 100000L; i++) {
        if (i % 1000 == 0) {
            Assert.assertNotEquals(defaultCRM.getAppInstanceID(), appInstanceID);
            appInstanceID = defaultCRM.getAppInstanceID();
        }
        ReqClientID r = defaultCRM.getReqClientID(); // This call is where memory use explodes.
        Assert.assertEquals(getNum(r.getClientRef()), new Long(i % 1000));
        Assert.assertEquals(r.getClientRef().length(), 14);
    }
    Thread.sleep(10000L);
}

The test is pretty simple: iterate 100K times to ensure that defaultCRM.getReqClientID() is generating a proper ReqClientID object with a valid counter between 000-999 and that a randomization prefix properly changes at rollover.

defaultCRM.getReqClientID() is where the memory problems occur. Let's take a look:

public ReqClientID getReqClientID() {
    ReqClientID req = new ReqClientID();
    req.setDID(datawireConfig.getDid()); // #1
    req.setApp(String.format("%s&%s", datawireConfig.getAppName(), versionConfig.toString())); // #2
    req.setAuth(String.format("%s|%s", datawireConfig.getMid(), datawireConfig.getTid())); // #3

    Long c = counter.getAndIncrement();
    String appID = appInstanceID;
    if(c >= 999L) {
        LOGGER.warn("Counter exceeds 3-digits. Resetting appInstanceID and counter.");
        resetAppInstanceID();
        counter.set(0L);
    }
    req.setClientRef(String.format("%s%s%03dV%s", datawireConfig.getNodeId(), appID, c, versionConfig.getDatawireVersion())); // #4
    return req;
}

Pretty simple: Create an object, call some String setters, calculate a incrementing counter, and random prefix on rollover.

Let's say I comment out the setters (ans associated assertions so they don't fail) numbered #1-#4 above. Memory use is now reasonable:

Originally I was using simple string concatenation using + in the setter components. I changed to String.format(), but that hasn't had any effect. I've also tried StringBuilder with append() to no effect.

I've also tried a few GC settings. In particular, I tried -XX:+UseG1GC, -XX:InitiatingHeapOccupancyPercent=35, and -Xms1g -Xmx1g (note that 1g is still unreasonable on my buildslave, and I'd like to get it down around max 256m). Here's the graph:

Going down to -Xms25m -Xmx256m causes OutOfMemoryError.

I'm confused by this behavior for third reasons. First, I don't understand the extreme growth in unused heap space in the first graph. I create an object, create some strings, pass the strings to the object, and delete the object by letting it go out of scope. Obviously, I don't expect perfect reuse of memory, but why is the JVM seemingly allocating more heap space for these objects every time? The way that unused heap space grows so substantially faster seems really, really wrong. Especially with the more aggressive GC settings, I'd expect to see the JVM attempt to reclaim these totally unreferenced objects before plowing through gigs of memory.

Second, in graph #2, it's apparent that the actual problem are the strings. I've tried to do some reading on ways to compose strings, literals/interned, etc., but I can't see many alternatives beyond +/String.format()/StringBuilder, which all seem to produce the same results. Am I missing some magical way to build strings?

Lastly, I know 100K iterations is overboard, and I could test the rollover with, say, 2K, but I'm trying to understand what's happening in the JVM.

System: OpenJDK x86_64 1.8.0_92 and also Hotspot x86_64 1.8.0_74.

Edit:

A couple of people recommended manually invoking System.gc() within the test, so I tried doing that every 1K loops. This has an appreciable impact on memory use and a woeful impact on performance:

The first thing to note is that while used heap space growth is slower, it's still unbounded. The only time it totally levels off is once the loop is finished, and the ending Thread.sleep() is invoked. A couple of questions:

1) Why is unused heap space still so high? During the very first loop iteration, System.gc() is invoked (i % 1000 == 0). That actually led to a drop in unused heap space. Why doesn't total heap space ever decrease after the first invocation?

2) Very roughly, every loop iteration 5 allocations are performed: inst ClientReqId and 4 strings. All references to all 5 objects are forgotten on each loop iteration. Total objects essentially remain static (varying only ~±5 objects) throughout the entire test. I still don't understand why System.gc() isn't more effective at holding used heap space constant when the number of live objects remains constant.

Edit 2: Solved

@Jonathan pointed me in the right direction by asking about mockedDatawireConfig. This is actually a Spring @ConfigurationProperties class (i.e. Spring loads data from a yaml into an instance and wires the instance where it's needed). In the unit test, I'm not employing anything related to Spring (unit test, not integration test). In this case, it's simply a POJO with getters and setters, but there's not logic in the class.

Anyways, the unit test was using a mocked version of this, which you can see in setup() above. I decided to switch to a real instance of the object instead of a mock. That completely solved the issue! It seems to be some issue with Mockito maybe inherent or perhaps since I appear to be using 2.0.2-beta. I'll investigate that further and contact the Mockito developers if it does appear to be an unknown issue.

Look at dat sweet, sweet graph: