H2 在第一次访问数据库时间歇性地遇到 ***Error

Posted 2023-03-31

【中文标题】H2 在第一次访问数据库时间歇性地遇到 ***Error

【英文标题】：H2 intermittently experiencing a ***Error when first hitting the database

【发布时间】：2021-10-14 19:34:23

【问题描述】：

我们的 H2 数据库 (v1.4.199) 有时会在我们的 Java Spring Boot 应用程序启动时在内部抛出一个 ***Error，并通过一个非常简单的 SELECT 查询针对单个表（即 第一个应用程序的查询。应用程序最终会正确启动，但只有在多次重启尝试后，每次都会抛出相同的***Error。鉴于它最终确实有效，这感觉不像是一个真正的无限递归问题。

这是来自h2.trace.db 日志的堆栈跟踪：

2021-08-02 13:46:15 database: flush
org.h2.message.DbException: General error: "java.lang.IllegalStateException: java.lang.***Error [1.4.199/3]" [50000-199]
    at org.h2.message.DbException.get(DbException.java:194)
    at org.h2.message.DbException.convert(DbException.java:347)
    at org.h2.mvstore.db.MVTableEngine$1.uncaughtException(MVTableEngine.java:90)
    at org.h2.mvstore.MVStore.handleException(MVStore.java:2787)
    at org.h2.mvstore.MVStore.panic(MVStore.java:441)
    at org.h2.mvstore.MVStore.store(MVStore.java:1194)
    at org.h2.mvstore.MVStore.tryCommit(MVStore.java:1135)
    at org.h2.mvstore.MVStore.writeInBackground(MVStore.java:2763)
    at org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:3123)
Caused by: org.h2.jdbc.JdbcSQLNonTransientException: General error: "java.lang.IllegalStateException: java.lang.***Error [1.4.199/3]" [50000-199]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:502)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:427)
    ... 9 more
Caused by: java.lang.IllegalStateException: java.lang.***Error [1.4.199/3]
    at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:883)
    ... 4 more
Caused by: java.lang.***Error
    at java.util.concurrent.ConcurrentHashMap.transfer(ConcurrentHashMap.java:2415)
    at java.util.concurrent.ConcurrentHashMap.addCount(ConcurrentHashMap.java:2288)
    at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1070)
    at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1619)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    at org.h2.mvstore.MVStore$ChunkIdsCollector.registerChunk(MVStore.java:1620)
    [invoking registerChunk() continues for another 1000 lines before being cut off...]

***Error 被包装为 IllegalStateException，然后在我们的应用程序日志中作为堆栈跟踪捕获：

org.h2.jdbc.JdbcSQLNonTransientException: General error: "java.lang.IllegalStateException: Reading from nio:/home/myapp/database/h2.mv.db failed; file length -1 read length 768 at 55238818159 [1.4.199/1]" [50000-199]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:502) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:427) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.message.DbException.get(DbException.java:194) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.message.DbException.convert(DbException.java:347) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Database.openDatabase(Database.java:345) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Database.<init>(Database.java:313) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Engine.openSession(Engine.java:69) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Engine.openSession(Engine.java:201) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Engine.createSession(Engine.java:161) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.Engine.createSession(Engine.java:31) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:169) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:148) ~[h2-1.4.199.jar:1.4.199]
    at org.h2.Driver.connect(Driver.java:69) ~[h2-1.4.199.jar:1.4.199]
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:136) ~[HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:369) ~[HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:198) ~[HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:467) [HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:541) [HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115) [HikariCP-3.2.0.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112) [HikariCP-3.2.0.jar:na]
    at org.apache.commons.dbutils.AbstractQueryRunner.prepareConnection(AbstractQueryRunner.java:319) [commons-dbutils-1.7.jar:1.7]
    at org.apache.commons.dbutils.QueryRunner.execute(QueryRunner.java:851) [commons-dbutils-1.7.jar:1.7]
    at com.mycompany.myapp.database.objectstores.h2.AppCache.<init>(AppCache.java:46) [main/:na]
    at com.mycompany.myapp.config.ObjectStore.database(ObjectStore.java:41) [main/:na]
    at com.mycompany.myapp.config.ObjectStore$$EnhancerBySpringCGLIB$$f5cc3c27.CGLIB$database$0(<generated>) [main/:na]
    at com.mycompany.myapp.config.ObjectStore$$EnhancerBySpringCGLIB$$f5cc3c27$$FastClassBySpringCGLIB$$94399cde.invoke(<generated>) [main/:na]
    at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:244) [spring-core-5.1.6.RELEASE.jar:5.1.6.RELEASE]

我们应用程序中的file length -1 read length 768 at 55238818159 错误非常令人担忧。

我们在 Java Spring Boot 应用程序中使用以下配置以文件模式运行 H2 数据库 (v1.4.199)：

    String url = "jdbc:h2:file:~/database/h2;"
            + "DB_CLOSE_ON_EXIT=FALSE;"
            + "AUTO_RECONNECT=TRUE;"
            + "DB_CLOSE_DELAY=-1;"
            + "MODE=mysql;";    
    
    return DataSourceBuilder.create()
        .username("sa")
        .url(url)
        .driverClassName(org.h2.Driver.class.getName()).build();

我们的数据库有 10 个表，每个表就像一个键/值存储，有几个 VARCHAR 列作为复合唯一键，然后一个 CLOB 通常保存大量 JSON 数据。它看起来像这样：

CREATE TABLE IF NOT EXISTS table_name (
  keypart1 VARCHAR,
  keypart2 VARCHAR,
  keypart3 VARCHAR,
  json_value CLOB,
  primary key (keypart1, keypart2, keypart3)
)

大多数表有几百或几千条记录，CLOB 值较小，而我们最大的表有 20k 条记录，CLOB 值从 2mb 到 120mb（平均为 4mb）。 h2.mv.db 文件大小约为 50GB。

在出现此问题之前，该应用程序已经正常运行了 2 年。看起来stacktrace中的registerChunk(MVStore.java:1619)是H2遍历父/子数据块的地方，所以我想知道它是在释放空间，修复某种早期的损坏，还是我们大量的CLOB数据正在抛弃它不知何故。

有什么想法吗？提前致谢。

【参考方案1】：

找到了解决办法。首先，IllegalStateException 是一个红鲱鱼，所以我专注于***Error。看起来 H2 v1.4.199 在MvStore 中有一些糟糕的递归逻辑，当数据库超过某个大小或复杂度阈值时开始失败。通过使用 JVM -Xss10M 参数将堆栈大小从 256K（默认）增加到 10MB，H2 能够递归足够深以成功完成启动逻辑。

我还看到这个***Error 导致其他类型的IllegaStateException，例如：

Caused by: java.lang.RuntimeException: Unable to connect to H2
    at com.myapp.migrate.H2Db.<clinit>(H2Db.java:36)
    ... 3 more
Caused by: org.h2.jdbc.JdbcSQLNonTransientException: General error: "java.lang.IllegalStateException: This store is closed [1.4.199/4]" [50000-199]

以及我遇到的原始错误：

org.h2.jdbc.JdbcSQLNonTransientException: General error: "java.lang.IllegalStateException: Reading from nio:/home/myapp/database/h2.mv.db failed; file length -1 read length 768 at 55238818159 [1.4.199/1]" [50000-199]

这个***Error 似乎是不同故障的根本原因，但被重新抛出/重新包装为其他东西。