Skip to content

MVStoreException: Chunk 75737 not found [1.4.200/9] #2767

Closed

Description

@forchid

Version: h2 current master, Ubuntu 19.10 x86_64 GNU/Linux

Test case

java -Xmx128m LongTest --items 100000000 --threads 4 --iterates 20 --batch 100
22:18:56.069>> iterates 20, items [0 - 100000000), threads 4, batch 100, tryCommit true, dbSize 20489M
22:18:56.076[iterate-0] Open MVStore 'long-test.db'
22:19:14.126[iterate-0] MVStore opened: time 18050ms, dbSize 20489M
22:19:14.140[iterate-0] Wait for test completion
Exception in thread "worker-1" org.h2.mvstore.MVStoreException: Chunk 75737 not found [1.4.200/9]
	at org.h2.mvstore.DataUtils.newMVStoreException(DataUtils.java:1001)
	at org.h2.mvstore.MVStore.getChunk(MVStore.java:1357)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:2535)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:629)
	at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1089)
	at org.h2.mvstore.CursorPos.traverseDown(CursorPos.java:58)
	at org.h2.mvstore.MVMap.operate(MVMap.java:1748)
	at org.h2.mvstore.MVMap.put(MVMap.java:156)
	at LongTest.test(LongTest.java:100)
	at LongTest.lambda$main$0(LongTest.java:61)
	at java.base/java.lang.Thread.run(Thread.java:830)
Exception in thread "main" java.lang.AssertionError: Expect count 100000000 but 99797335
	at LongTest.main(LongTest.java:77)

Test code

import org.h2.mvstore.*;
import java.util.*;
import java.text.*;
import java.io.*;
import java.util.concurrent.atomic.*;

public class LongTest {

  public static void main(String[] args) {
    DateFormat df = new SimpleDateFormat("HH:mm:ss.SSS");
    
    int iterates = 1;
    int threads = 1;
    int items = 10000000;
    int batch = 100;
    String db = "long-test.db";
    boolean tryCommit = true;
    
    for (int i = 0, n = args.length; i < n; ++i) {
      String arg = args[i];
      if ("--iterates".equals(arg)) {
        iterates = Integer.decode(args[++i]);
      } else if ("--threads".equals(arg)) {
        threads = Integer.decode(args[++i]);
      } else if ("--items".equals(arg)) {
        items = Integer.decode(args[++i]);
      } else if ("--batch".equals(arg)) {
        batch = Integer.decode(args[++i]);
      } else if ("--db".equals(arg)) {
        db = args[++i];
      } else if ("--try-commit".equals(arg)) {
        tryCommit = Boolean.parseBoolean(args[++i]);
      }
    }
    long dbSize = new File(db).length();
    System.out.println(String.format("%s>> iterates %d, items [0 - %d), threads %d, batch %d, tryCommit %s, dbSize %dM", 
      df.format(new Date()), iterates, items, threads, batch, tryCommit, dbSize >> 20));

    final long ts = System.currentTimeMillis();
    for (int j = 0; j < iterates; ++j) {
      final long ta = System.currentTimeMillis();
      String time = df.format(new Date());
      System.out.println(String.format("%s[iterate-%d] Open MVStore '%s'", time, j, db));
      try (final MVStore store = MVStore.open(db)) {
        final long to = System.currentTimeMillis();
        dbSize = new File(db).length();
        time = df.format(new Date());
        System.out.println(String.format("%s[iterate-%d] MVStore opened: time %dms, dbSize %dM", 
          time, j, to - ta, dbSize >> 20));
        final Thread[] workers = new Thread[threads];
        final boolean tryco = tryCommit;
        int step = items / threads;
        int rem = items % threads;
        int txBatch = batch;
        final AtomicInteger count = new AtomicInteger();
      
        for (int i = 0; i < threads; ++i) {
          final int offset = i * step;
          final int range = (i == threads - 1? step + rem: step);
          Thread t = new Thread(() -> {
              int n = test(store, offset, range, txBatch, tryco);
              count.set(n);
            }, "worker-" + i);
          t.setDaemon(true);
          workers[i] = t;
          t.start();
        }
        
        time = df.format(new Date());
        System.out.println(String.format("%s[iterate-%d] Wait for test completion", time, j));
        for (int i = 0; i < threads; ++i) {
          Thread t = workers[i];
          try {
            t.join();
          } catch(InterruptedException ignore){}
        }
        if (count.get() != items) throw new AssertionError("Expect count " + items + " but " + count);
      }
      dbSize = new File(db).length();
      
      final long tb = System.currentTimeMillis();
      time = df.format(new Date());
      System.out.println(String.format("%s[iterate-%d] Time %dms, items %d, threads %d, batch %d, tryCommit %s, dbSize %dM", 
        time, j, tb - ta, items, threads, batch, tryCommit, dbSize >> 20));
    }
    dbSize = new File(db).length();

    final long te = System.currentTimeMillis();
    System.out.println(String.format("%s<< time %dms, iterates %d, items [0 - %d), threads %d, batch %d, tryCommit %s, dbSize %dM", 
      df.format(new Date()), te - ts, iterates, items, threads, batch, tryCommit, dbSize >> 20));
    System.out.println();
  }

  static int test(MVStore store, int offset, int range, int batch, boolean tryCommit) {
    MVMap<Integer, String> map = store.openMap("data");
    String prefix = "Bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-bar-";
    
    for (int i = offset, n = i + range; i < n; ++i) {
      String value = prefix + i;
      map.put(i, value);
      if (i > offset && i % batch == 0 || i == n - 1) {
        String last = map.get(i);
        if (!last.equals(value)) {
          throw new AssertionError("Last value not matched at i " + i);
        }
        if (tryCommit) store.tryCommit();
        else store.commit();
      }
    }
    return map.size();
  }

}

Activity

  1. andreitokar commented on Jul 18, 2020

    @andreitokar
    Contributor

    Is it reproducible?

  2. andreitokar commented on Jul 19, 2020

    @andreitokar
    Contributor

    I can not reproduce it.
    BTW, Your assumption

    if (count.get() != items) throw new AssertionError("Expect count " + items + " but " + count);
    

    is incorrect, because thread with finish insertion last (and sees the full map with expected size) is not nesseccary the same thread which would do last assignment to count.

    07:59:45.345>> iterates 20, items [0 - 100000000), threads 4, batch 100, tryCommit true, dbSize 0M
    07:59:45.352[iterate-0] Open MVStore 'data/LittlePan_2767'
    07:59:45.542[iterate-0] MVStore opened: time 190ms, dbSize 0M
    07:59:45.550[iterate-0] Wait for test completion
    Exception in thread "main" java.lang.AssertionError: Expect count 100000000 but 25000000
    	at org.h2.test.LittlePan_2767.main(LittlePan_2767.java:84)
    	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.lang.reflect.Method.invoke(Method.java:498)
    	at com.intellij.rt.execution.application.AppMainV2.main(AppMainV2.java:128)
    
  3. forchid commented on Jul 19, 2020

    @forchid
    ContributorAuthor

    It's one of my intents: the count 25000000 itself is incorrect for 4 thread insertion after any last insertion. This count should be bigger than 25000000.
    Reproducing this issue is very difficult😂. Since last month, only one time.

  4. andreitokar commented on Jan 3, 2021

    @andreitokar
    Contributor

    It just occurred to me that MVStore.registerVersionUsage()/deregisterVersionUsage() are not used in you example.
    That means use of unprotected version and "Chunk not found" error is totally expected.
    Each map access (or group of map operations) has to be protected by those calls. Otherwise version of the store may be garbage collected, while map operation (within this store version) is still in progress. Even a simple get() access is in fact a multi-step process of B-tree traversal from root to leaf and may fail at any step if required page has been removed already.
    Map operations are not wrapped with such calls by default due to possible performance overhead, but it's trivial to create such "safe" wrapper for MVMap.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions