Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

org.h2.mvstore.MVStoreException: Chunk not found [2.2.224/9] #4012

Closed
cdprete opened this issue Feb 28, 2024 · 26 comments · Fixed by #4047
Closed

org.h2.mvstore.MVStoreException: Chunk not found [2.2.224/9] #4012

cdprete opened this issue Feb 28, 2024 · 26 comments · Fixed by #4047
Labels

Comments

@cdprete
Copy link

cdprete commented Feb 28, 2024

Hi.

While executing a query and "streaming" the content of the ResultSet I get a "Chunk XYZ not found" exception.

org.h2.jdbc.JdbcSQLNonTransientException: General error: "org.h2.mvstore.MVStoreException: Chunk 19794087 not found [2.2.224/9]" [50000-224]
        at org.h2.message.DbException.getJdbcSQLException(DbException.java:566)
        at org.h2.message.DbException.getJdbcSQLException(DbException.java:489)
        at org.h2.message.DbException.get(DbException.java:212)
        at org.h2.message.DbException.convert(DbException.java:407)
        at org.h2.message.DbException.toSQLException(DbException.java:379)
        at org.h2.message.TraceObject.logAndConvert(TraceObject.java:365)
        at org.h2.jdbc.JdbcResultSet.next(JdbcResultSet.java:127)
        at com.zaxxer.hikari.pool.HikariProxyResultSet.next(HikariProxyResultSet.java)
        at com.sixgroup.cit.fmd.eodmaster.cmp.repository.internal.ResultSetStream$1.tryAdvance(ResultSetStream.kt:21)
        at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:129)
        at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:527)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:513)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
        at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)

Can you please provide some help on why this is happening and how to solve it?

Kind regards and thanks.

@grandinj
Copy link
Contributor

Your database is corrupt. You will need to recover it from backups.

@cdprete
Copy link
Author

cdprete commented Feb 29, 2024

Well, it happens all the time, even if I drop the db and start freshly.
If I don't have nested Java queries though, then it works fine.

@grandinj
Copy link
Contributor

If you can build a standalone test case (i.e. just Java, no depencies), we can probably have a bash at fixing it

@grandinj
Copy link
Contributor

You might also want to try doing a build from current HEAD and seeing it that fixes your issue, a few things have been fixed since the last release

@cdprete
Copy link
Author

cdprete commented Feb 29, 2024

Mmm I can try.
For now I've dropped the nested queries in favor of one big query with fetchSize = 1 on the ResultSet.

@cdprete
Copy link
Author

cdprete commented Mar 2, 2024

I've spoken too early.
Even with a single query and fetchSize = 1 I get the same error from time to time.

Caused by: org.h2.mvstore.MVStoreException: Chunk 1345210 not found [2.2.224/9]
at org.h2.mvstore.DataUtils.newMVStoreException(DataUtils.java:996)
at org.h2.mvstore.FileStore.getChunk(FileStore.java:2006)
at org.h2.mvstore.FileStore.readPage(FileStore.java:1953)
at org.h2.mvstore.MVStore.readPage(MVStore.java:1021)
at org.h2.mvstore.MVMap.readPage(MVMap.java:632)
at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1117)
at org.h2.mvstore.Cursor.hasNext(Cursor.java:64)
at org.h2.mvstore.tx.TransactionMap$CommittedIterator.fetchNext(TransactionMap.java:960)
at org.h2.mvstore.db.MVSecondaryIndex$MVStoreCursor.next(MVSecondaryIndex.java:434)
at org.h2.index.IndexCursor.next(IndexCursor.java:292)
at org.h2.table.TableFilter.next(TableFilter.java:425)
at org.h2.command.query.Select$LazyResultQueryFlat.fetchNextRow(Select.java:1843)
at org.h2.result.LazyResult.hasNext(LazyResult.java:78)
at org.h2.result.FetchedResult.next(FetchedResult.java:34)
at org.h2.jdbc.JdbcResultSet.nextLazyRow(JdbcResultSet.java:3608)
at org.h2.jdbc.JdbcResultSet.nextRow(JdbcResultSet.java:3593)
at org.h2.jdbc.JdbcResultSet.next(JdbcResultSet.java:125)
... 43 common frames omitted

The ResultSet is consumed as a Stream with

import org.h2.util.IOUtils.closeSilently
import org.slf4j.LoggerFactory
import java.sql.ResultSet
import java.sql.SQLException
import java.util.Spliterators.AbstractSpliterator
import java.util.function.Consumer
import java.util.stream.Stream
import java.util.stream.StreamSupport.stream
import kotlin.Long.Companion.MAX_VALUE

/**
 * @author Cosimo Damiano Prete
 * @since 09/02/2024
 **/
class ResultSetStream<E>(
    private val resultSet: ResultSet,
    private inline val isClosed: () -> Boolean,
    private inline val rowMapper: (ResultSet) -> E
): Stream<E> by stream(object: AbstractSpliterator<E>(MAX_VALUE, ORDERED or DISTINCT or SORTED or NONNULL or IMMUTABLE) {
    override fun tryAdvance(action: Consumer<in E>) = try {
        val hasNext = !isClosed() && resultSet.next()
        if(hasNext) action.accept(rowMapper(resultSet))

        hasNext
    } catch (ex: SQLException) {
        logger.error(ex.toString(), ex)
        false
    }

    override fun getComparator() = null
}, false) {
    init {
        resultSet.fetchSize = 1
        onClose {
            val statement = resultSet.statement
            val connection = statement.connection

            closeSilently(resultSet)
            closeSilently(statement)
            closeSilently(connection)
        }
    }

    private companion object {
        @JvmStatic
        private val logger = LoggerFactory.getLogger(ResultSetStream::class.java)
    }
}

@ejwilburn
Copy link

ejwilburn commented Mar 15, 2024

We're seeing the same issue as well, it seems to be exacerbated by running on slow storage mediums such as spinning disks or VMs with virtual storage like Amazon Workspaces when working with large data sets (10M+ rows across several tables, 5+GB database size). In our case we use H2 as a temporary database that is recreated with a new temp file name every time the application is started, so it shouldn't be a database corruption issue.

One of the instances we've seen recur is the stack trace you have above from running a basic query, though that usually triggers after loading those 10M+ rows, then updating them all a couple of times then querying immediately after. The updates are done in parallel streams and the query that triggers the error happens immediately after once all updates are complete.

Another variation of this error occurs for us when doing a large INSERT INTO SELECT FROM statement that inserts millions of rows into an empty table with no other processing occurring in parallel, no tables involved are being modified by anything else while that's processing:

Caused by: org.h2.mvstore.MVStoreException: Chunk 3049 not found [2.2.224/9]
	at org.h2.mvstore.DataUtils.newMVStoreException(DataUtils.java:996)
	at org.h2.mvstore.FileStore.getChunk(FileStore.java:2006)
	at org.h2.mvstore.FileStore.readPage(FileStore.java:1953)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:1021)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:632)
	at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1117)
	at org.h2.mvstore.Cursor.hasNext(Cursor.java:64)
	at org.h2.mvstore.tx.TransactionMap$CommittedIterator.fetchNext(TransactionMap.java:960)
	at org.h2.mvstore.db.MVSecondaryIndex$MVStoreCursor.next(MVSecondaryIndex.java:434)
	at org.h2.index.IndexCursor.next(IndexCursor.java:292)
	at org.h2.table.TableFilter.next(TableFilter.java:425)
	at org.h2.command.dml.FilteredDataChangeStatement.nextRow(FilteredDataChangeStatement.java:71)
	at org.h2.command.dml.Delete.update(Delete.java:58)
	at org.h2.command.dml.DataChangeStatement.update(DataChangeStatement.java:74)
	at org.h2.command.CommandList.executeRemaining(CommandList.java:49)
	at org.h2.command.CommandList.update(CommandList.java:66)
	at org.h2.command.Command.executeUpdate(Command.java:256)

Our code base is quite large and I've tried to create a simplified example to repro the issue but so far haven't had much success. Reproducing it in our code base is still intermittent and takes hours of processing to trigger. The most success I've had is plugging in an old spinning disk and moving the DB to that drive for testing.

@cdprete
Copy link
Author

cdprete commented Mar 15, 2024

We're seeing the same issue as well, it seems to be exacerbated by running on slow storage mediums such as spinning disks or VMs with virtual storage like Amazon Workspaces when working with large data sets (10M+ rows across several tables, 5+GB database size). In our case we use H2 as a temporary database that is recreated with a new temp file name every time the application is started, so it shouldn't be a database corruption issue.

One of the instances we've seen recur is the stack trace you have above from running a basic query, though that usually triggers after loading those 10M+ rows, then updating them all a couple of times then querying immediately after. The updates are done in parallel streams and the query that triggers the error happens immediately after once all updates are complete.

Another variation of this error occurs for us when doing a large INSERT INTO SELECT FROM statement that inserts millions of rows into an empty table with no other processing occurring in parallel, no tables involved are being modified by anything else while that's processing:

Caused by: org.h2.mvstore.MVStoreException: Chunk 3049 not found [2.2.224/9]
	at org.h2.mvstore.DataUtils.newMVStoreException(DataUtils.java:996)
	at org.h2.mvstore.FileStore.getChunk(FileStore.java:2006)
	at org.h2.mvstore.FileStore.readPage(FileStore.java:1953)
	at org.h2.mvstore.MVStore.readPage(MVStore.java:1021)
	at org.h2.mvstore.MVMap.readPage(MVMap.java:632)
	at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1117)
	at org.h2.mvstore.Cursor.hasNext(Cursor.java:64)
	at org.h2.mvstore.tx.TransactionMap$CommittedIterator.fetchNext(TransactionMap.java:960)
	at org.h2.mvstore.db.MVSecondaryIndex$MVStoreCursor.next(MVSecondaryIndex.java:434)
	at org.h2.index.IndexCursor.next(IndexCursor.java:292)
	at org.h2.table.TableFilter.next(TableFilter.java:425)
	at org.h2.command.dml.FilteredDataChangeStatement.nextRow(FilteredDataChangeStatement.java:71)
	at org.h2.command.dml.Delete.update(Delete.java:58)
	at org.h2.command.dml.DataChangeStatement.update(DataChangeStatement.java:74)
	at org.h2.command.CommandList.executeRemaining(CommandList.java:49)
	at org.h2.command.CommandList.update(CommandList.java:66)
	at org.h2.command.Command.executeUpdate(Command.java:256)

Our code base is quite large and I've tried to create a simplified example to repro the issue but so far haven't had much success. Reproducing it in our code base is still intermittent and takes hours of processing to trigger. The most success I've had is plugging in an old spinning disk and moving the DB to that drive for testing.

Too bad that on my side I've the DB file on an SSD :-/

@ejwilburn
Copy link

Too bad that on my side I've the DB file on an SSD :-/

Yeah, it doesn't happen only on slower drives I just think slower drives reproduce the issue more easily.

@cdprete
Copy link
Author

cdprete commented Mar 15, 2024

@ejwilburn but, indeed, I think we agree it happens for large data sets for both of us.

@ejwilburn
Copy link

ejwilburn commented Apr 12, 2024

So I've continued looking into this issue and managed to create a test that repros reliably in our main code base, though I haven't finished creating a simplified version I can share with the H2 team yet, but in essence here's what the code does:

  1. inserts 200,000 records into table A
  2. inserts 35 records per record in table A into table B (and also into a third table that isn't used further in this case to mimic our primary process), so 7 million records total in table B and another 7 million in the unused table
  3. does an INSERT INTO table C SELECT FROM table A joined to table B WHERE NOT EXISTS (in table C) - 7M records total, this step causes a chunk not found exception reliably

The query itself is somewhat more complex than that, including a window function, but that's the jist. I tried a variety of H2 options to see if anything would help, turning off lazy querying, changing page sizes, trying ACCESS_MODE_DATA=rwd and rws and finally adjusting WRITE_DELAY. Using a higher WRITE_DELAY has fixed the issue for me so far, I'm currently testing larger and larger data sets to see if/when it breaks down. I've only tested setting it to 5000 (5 seconds), which is 10 times the default.

Currently up to 9M total records without issue and trying 15M next, though running these tests on a spinning disk to make reproduction easier takes a very long time. Last run of 15M took ~10 hours before it failed. However, the runs with 7M total records in the output table were failing reliably in about 90 minutes.

My guess is that increasing the write delay is just increasing the point at which this error starts to occur reliably, not really a fix for the underlying cause and obviously increasing the write delay that much has reliability concerns in situations where you care about recovery if there's a power/system failure.

@andreitokar

@andreitokar
Copy link
Contributor

@ejwilburn Thank you for posting a status update.

Why would you try to turn any knob possible, when it is hard to reproduce failure even for a given set of configuration parameters? I would focus on that first case of yours, where you were able to reproduce it.

@ejwilburn
Copy link

ejwilburn commented Apr 12, 2024

@ejwilburn Thank you for posting a status update.

Why would you try to turn any knob possible, when it is hard to reproduce failure even for a given set of configuration parameters? I would focus on that first case of yours, where you were able to reproduce it.

@andreitokar Because I was able to get a case I could reproduce consistently and I was looking for options to resolve this issue in our application as soon as possible.

Upping the WRITE_DELAY did fix it for that first case, now I'm trying larger cases to ensure this actually solves it for larger data set sizes we know we need to support. Finding the smallest data set size I could repro with was necessary to be able to test different possible options in the shortest amount of time possible, which was still about 90 minutes per run, now I'm scaling that up to much longer running tests to confirm it's a viable solution.

@ejwilburn
Copy link

ejwilburn commented Apr 13, 2024

This is definitely related to WRITE_DELAY, my guess without knowing the internals is that if the write delay is set too low where it's taking longer to actually write the data to disk than the configured write delay it starts causing corruption after the data set reaches a certain size. With a write delay of 5 seconds I'm not seeing any corruption issues with a database up to ~45.5M total records (between table A, B, C and the unused one in my example). If I set the write delay to 5ms I can repro the corruption with just ~1.9M total records between all tables.

So to summarize:

Write Delay Total Records to Repro
5 1,860,000
Default (500) 21,200,000
5000 Tested up to 45,500,000 with no error

@andreitokar

@vreuland
Copy link
Contributor

Hello,
I am also interested by this case (mostly to anticipate if I could run into a similar issue in the future to be honest).
Thank you @ejwilburn for all those details.

If I am not mistaken, WRITE_DELAY is also driving how frequent the background housekeeping is performed (i.e. rewriting and dropping chunks). I can only guess there is a "race condition" occuring between the"insert from select" and the housekeeping. The more frequent the housekeeping is performed (ie. the lower is WRITE_DELAY), the more chances you have to hit that race condition I suppose....

Note that there were some changes in latest versions (2.2.222 / 2.2.224) to trigger the chunk rewrites more often (cf. #3848). I am wondering if you can reproduce the error using H2 version 2.1.214 for instance.

In any case, I believe that to find the root cause and a fix, a simplified test case that reproduce the error will be needed.

And I am looking forward to having @andreitokar's opinion on this.

Kr,
Vincent

@ejwilburn
Copy link

ejwilburn commented Apr 13, 2024

In theory I should be able to repro with just the standalone server and a basic SQL script using SYSTEM_RANGE(), I'll play around with that.

@ejwilburn
Copy link

ejwilburn commented Apr 19, 2024

Finally got a stand alone app that reproduces the issue using JDBC: https://github.com/ejwilburn/h2-chunk-not-found

Details are in the readme. I did try creating a SQL script to do this in just a stand-alone H2 server but it didn't repro the issue, possibly due to the difference between inserting the individual records via JDBC vs. generating them using SELECT FROM SYSTEM_RANGE() since that would be a single transaction instead of many. Also the script was waaay slower than inserting the records one at a time via JDBC for some reason. 🤷

Going to try downgrading to 2.1.214 and see if that has any effect.

@vreuland @andreitokar

@ejwilburn
Copy link

The first few runs of 2.1.214 aren't reproducing the issue, trying larger datasets to see if that has any impact.

@ejwilburn
Copy link

2.1.214 did reproduce when I upped the amount of data in the test by five times, so it looks like the changes in 2.2.222/2.2.224 exacerbated the issue but aren't the root cause.

@ejwilburn
Copy link

ejwilburn commented Apr 21, 2024

FYI, did more testing and raising the write delay to just 1000, or double the default, was enough to prevent the issue. I tested in a DB with about 65M total records. Watching Windows performance meter while heavy writes were going on, the response time from the drive was frequently in the high 400ms range and was likely peaking over 500ms at times, which again makes me think this is an issue when the time to write to the drive is longer than the write delay.

@andreitokar
Copy link
Contributor

@ejwilburn Thank You very much for creating that test case.
I think, I got it now, what the problem is, and although it is not a hard proof, I was not able to reproduce the problem any more, after I applied my fix, neither in original form, nor after I multiplied NUMBER_OF_DUPLICATE_GROUPS and GROUP_SIZE by two, and end up with 35GB database.
The problem seems related with the fact, that when a few statements are sent as a single JDBC call, all but the first SQL statements were executed without proper prologue/epilogue code, which includes MVStore.registerVersionUsage() and MVStore.deregisterVersionUsage() calls, protecting affected versions of database from being garbage collected.
Creating pull request now.

@andreitokar
Copy link
Contributor

On master now.
@ejwilburn If you can build it from the current master branch and verify that issue is gone now for your cases...

@ejwilburn
Copy link

Initial test looks good, running some larger tests and will report back.

FYI we ran into a similar issue with large queries when lazy query execution is enabled and I think it's somewhat related in that the versions being used by that lazy query aren't being marked as used and are being GC'd before the next chunk of the query is returned, resulting in the chunk not found error. We worked around that by just disabling lazy query execution, which isn't ideal for us. I know that used to be marked as an experimental feature in the docs but doesn't appear to be anymore.

Would you like me to open another issue for that? Not sure when I'd have time to create a simple repro for that.

@andreitokar

@ejwilburn
Copy link

Longer test finished with no problems, looks like #4047 fixed it.

@cdprete
Copy link
Author

cdprete commented Apr 26, 2024

@ejwilburn Thank You very much for creating that test case. I think, I got it now, what the problem is, and although it is not a hard proof, I was not able to reproduce the problem any more, after I applied my fix, neither in original form, nor after I multiplied NUMBER_OF_DUPLICATE_GROUPS and GROUP_SIZE by two, and end up with 35GB database. The problem seems related with the fact, that when a few statements are sent as a single JDBC call, all but the first SQL statements were executed without proper prologue/epilogue code, which includes MVStore.registerVersionUsage() and MVStore.deregisterVersionUsage() calls, protecting affected versions of database from being garbage collected. Creating pull request now.

That's fancy because in my case I'm always sending a single prepared statement with a single instruction into it every time.

@cdprete
Copy link
Author

cdprete commented May 2, 2024

On master now. @ejwilburn If you can build it from the current master branch and verify that issue is gone now for your cases...

Hi @andreitokar.

Would it be possible to get it released so that I can test it also from my side?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants