StackOverflowError at org.h2.mvstore.MVMap.put

[sanderPostma]

I am running into the following exception while doing a very basic batch of inserts:
java.lang.StackOverflowError
at org.h2.mvstore.MVMap.put(MVMap.java:185)
at org.h2.mvstore.MVMap.put(MVMap.java:211)
at org.h2.mvstore.MVMap.put(MVMap.java:209)
at org.h2.mvstore.MVMap.put(MVMap.java:211)
at org.h2.mvstore.MVMap.put(MVMap.java:209)
at org.h2.mvstore.MVMap.put(MVMap.java:211)
at org.h2.mvstore.MVMap.put(MVMap.java:209)
at org.h2.mvstore.MVMap.put(MVMap.java:211)
at org.h2.mvstore.MVMap.put(MVMap.java:209)
at org.h2.mvstore.MVMap.put(MVMap.java:211)
at org.h2.mvstore.MVMap.put(MVMap.java:209)
at org.h2.mvstore.MVMap.put(MVMap.java:211)

Steps to reproduce:

• Download and unpack nitrite-stresstest.zip

• Go the the unpack folder and run
  gradlew.bat test

• Open build\test-results\test\TEST-org.dizitart.testing.NitriteStressTest.xml to see the result

The insert loop crashes after roughly 7200 records while I need to insert double of that. This i just a couple of MB's of data so this should not be a problem.

[anidotnet]

Strange! I ran your code but it went successfully without any error.

If it helps, my workstation is Ubuntu 17.04 - 64 bit with 16GB memory. Can you dig down a bit more and test it out in a different environment just to pin point the root cause?

[sanderPostma]

On my Win10 workstation the test crashes after 19 seconds with a StackOverflow.
But the stack size on Windows is much lower than on Linux, like only 250.
I tried the same test in an Ubuntu 16 VM with 5GB, there the test runs for a whole minute, then it crashes with:
<testcase name="stressTest" classname="org.dizitart.testing.NitriteStressTest" time="59.335"> <failure message="java.lang.OutOfMemoryError: GC overhead limit exceeded" type="java.lang.OutOfMemoryError">java.lang.OutOfMemoryError: GC overhead limit exceeded at org.h2.mvstore.Page.splitNode(Page.java:400) at org.h2.mvstore.Page.split(Page.java:371) at org.h2.mvstore.MVMap.put(MVMap.java:205) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211) at org.h2.mvstore.MVMap.put(MVMap.java:209) at org.h2.mvstore.MVMap.put(MVMap.java:211)
On java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

Again inside a a page split loop in mvstore.MVMap.put where the problem seems to be in:
`

protected Object put(Page p, long writeVersion, Object key, Object value) {
...
...
Page c = p.getChildPage(index).copy(writeVersion);
if (c.getMemory() > store.getPageSplitSize() && c.getKeyCount() > 1) {
// split on the way down
int at = c.getKeyCount() / 2;
Object k = c.getKey(at);
Page split = c.split(at);
p.setChild(index, split);
p.insertNode(index, k, c);
// now we are not sure where to add
return put(p, writeVersion, key, value);
}
Object result = put(c, writeVersion, key, value);
p.setChild(index, c);
return result;
}
`
It looks like it's creating maps of only 11 records. After 11 records it splits the map, adds them as child node to the current page and self-calls the method. No wonder that after 15000 records the stack goes 1363 calls deep and the map containers occupy more space than the actual data.
Something is very wrong here anyway, when I put a breakpoint in line " if (c.getMemory() > store.getPageSplitSize() && c.getKeyCount() > 1) {" I see that for every insert it stops a few times on this line. 6 times for the first insert. And for every two new inserts after that it stops there one additional time.
Increasing the page size by a factor 1000 might help, but the whole concept of getting a deeper call stack for every other insert seems very wrong.
Please put your breakpoint on MVMap line 201 and see if you get the same behavior.

[anidotnet]

Nice finding. Strange thing is after couple of tries, I am able to reproduce this SOE now. Don't know why this was not caught the first time I tried. I'll try to look into it more deeply to see if anything can be tuned from Nitrite's code to avoid this. Meanwhile, it would be sensible to log an issue with the h2database team here, after all, they are the maintainer of mvstore library.

Another curious thing I observed is that this SOE does not happen if you chose a file store, instead of in-memory store. This is also worth mentioning.

[zaphod72]

This appears to be caused by the decreasing NitriteId values as the keys in the MVStore.
Here's a repro with only H2 -

This fails:

    public void stressTestMVStore() {
    	MVStore.Builder builder = new MVStore.Builder();
    	MVStore store = builder.open();
    	store.commit();
    	MVMap<IdTest, Integer> map = store.openMap("test");

        for (int id = 0; id < TEST_SET_COUNT; id++) {
            map.put(new IdTest(id), id);
        }
    }

But just changing it to use increasing id values and it succeeds, and runs much faster:

    	MVStore.Builder builder = new MVStore.Builder();
    	MVStore store = builder.open();
    	store.commit();
    	MVMap<IdTest, Integer> map = store.openMap("test");

    	for (int id = TEST_SET_COUNT; id > 0; id--) {
            map.put(new IdTest(id), id);
        }
    }

IdTest:

    class IdTest implements Serializable, Comparable<IdTest> {
		private static final long serialVersionUID = -5121329963558106704L;
		
		private Integer id;
    	
    	public IdTest(Integer id) {
    		this.id = id;
    	}

        @Override
        public int compareTo(IdTest other) {
            return id.compareTo(other.id);
        }
    }

[anidotnet]

Thanks for debugging it and publishing it here. I already have a mechanism in place for the fix, I just did not get the time to commit the code here. It will be committed here shortly.