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

Jump to bottom

MVStore writes become unnaturally slow #1570

Closed
offbynull opened this issue Nov 22, 2018 · 4 comments
Closed

MVStore writes become unnaturally slow #1570

offbynull opened this issue Nov 22, 2018 · 4 comments

Comments

@offbynull
Copy link

Version: 1.4.197

I'm creating and populating 32 different file databases in the same process. Each database is structured the same: default settings with 3 tables each having a primary key and a index but no foreign keys.

After about 2 hours of continuous MERGEs in batches of 10000, the database slows to a crawl. System stats show that the process is spending a ton of time reading but only a small window for writing.

Just from inspecting the stacktraces, it looks like...

  1. a ton of time is being spent in MVStore.commit/commitAndStore:
app//org.h2.mvstore.MVStore.commitAndSave(MVStore.java:983)
app//org.h2.mvstore.MVStore.beforeWrite(MVStore.java:2205)
app//org.h2.mvstore.MVMap.beforeWrite(MVMap.java:1008)
app//org.h2.mvstore.MVMap.put(MVMap.java:120)
   - locked org.h2.mvstore.MVMap@35ba4341
app//org.h2.mvstore.db.TransactionStore.log(TransactionStore.java:295)
app//org.h2.mvstore.db.TransactionStore$Transaction.log(TransactionStore.java:734)
app//org.h2.mvstore.db.TransactionStore$TransactionMap.trySet(TransactionStore.java:1139)
app//org.h2.mvstore.db.TransactionStore$TransactionMap.set(TransactionStore.java:1063)
app//org.h2.mvstore.db.TransactionStore$TransactionMap.put(TransactionStore.java:1042)
app//org.h2.mvstore.db.MVSecondaryIndex.add(MVSecondaryIndex.java:206)
app//org.h2.mvstore.db.MVTable.addRow(MVTable.java:732)
app//org.h2.command.dml.Merge.merge(Merge.java:183)
app//org.h2.command.dml.Merge.update(Merge.java:116)
app//org.h2.command.CommandContainer.update(CommandContainer.java:102)
app//org.h2.command.Command.executeUpdate(Command.java:261)
   - locked org.h2.engine.Database@b09ee15
app//org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:199)
   - locked org.h2.engine.Session@67f24041
app//org.h2.jdbc.JdbcPreparedStatement.executeBatch(JdbcPreparedStatement.java:1277)
app//com.netrias.ade.db.h2.H2Database.lambda$insertMeasurementProperties$5(H2Database.java:297)
app//com.netrias.ade.db.h2.H2Database$$Lambda$68/366252104.execute(Unknown Source)
app//com.netrias.ade.db.h2.H2Database.lambda$spread$8(H2Database.java:652)
app//com.netrias.ade.db.h2.H2Database$$Lambda$59/1101048445.call(Unknown Source)
java.base@10.0.1/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base@10.0.1/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
java.base@10.0.1/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.base@10.0.1/java.lang.Thread.run(Thread.java:844)
  1. The MVStore background writer thread is spending a ton of time in reading:
java.base@10.0.1/sun.nio.ch.FileDispatcherImpl.pread0(Native Method)
java.base@10.0.1/sun.nio.ch.FileDispatcherImpl.pread(FileDispatcherImpl.java:60)
java.base@10.0.1/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:280)
java.base@10.0.1/sun.nio.ch.IOUtil.read(IOUtil.java:250)
java.base@10.0.1/sun.nio.ch.FileChannelImpl.readInternal(FileChannelImpl.java:818)
java.base@10.0.1/sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:799)
   - locked java.lang.Object@28ea36e8
app//org.h2.store.fs.FileNio.read(FilePathNio.java:74)
app//org.h2.mvstore.DataUtils.readFully(DataUtils.java:403)
app//org.h2.mvstore.FileStore.readFully(FileStore.java:98)
app//org.h2.mvstore.Page$PageChildren.read(Page.java:1055)
app//org.h2.mvstore.MVStore.readPageChunkReferences(MVStore.java:1356)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1301)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1306)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1306)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1306)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1306)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1306)
app//org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1286)
app//org.h2.mvstore.MVStore.freeUnusedChunks(MVStore.java:1248)
   - locked org.h2.mvstore.MVStore@ff2038c
app//org.h2.mvstore.MVStore.freeUnusedIfNeeded(MVStore.java:1238)
app//org.h2.mvstore.MVStore.storeNowTry(MVStore.java:1025)
app//org.h2.mvstore.MVStore.storeNow(MVStore.java:1016)
app//org.h2.mvstore.MVStore.commitAndSave(MVStore.java:1005)
   - locked org.h2.mvstore.MVStore@ff2038c
app//org.h2.mvstore.MVStore.writeInBackground(MVStore.java:2477)
app//org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:2713)

This is on a modern laptop with a SSD. The speed drops from 100ms-400ms per 10000 rows to 10000ms-60000ms. Is there any reason why H2 would slow down like this?

        INSERTED 20000 IN 319
        INSERTED 20000 IN 25782
        INSERTED 20000 IN 20831
        INSERTED 20000 IN 782
        INSERTED 20000 IN 22352
        INSERTED 20000 IN 22443
        INSERTED 20000 IN 23668
        INSERTED 20000 IN 22727
        INSERTED 20000 IN 1164
        INSERTED 20000 IN 47140
        INSERTED 20000 IN 1469
        INSERTED 12862 IN 790
@andreitokar
Copy link
Contributor

Can you reproduce this problem using current master branch (collectReferencedChunks has been modified recently)? If so can you provide some use case to work with?

@offbynull
Copy link
Author

This doesn't happen in master. The I/O rates are much more consistent, but the periodic compaction that's happening causes database access to block for a long time. At the tail end of my test, the compaction going on had my application code sitting for ~16 minutes (database was 115gb in size at this point).

Is this something that's tuneable via the JDBC URL parameters? Stack traces below...

java.base@10.0.1/sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
java.base@10.0.1/sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:74)
java.base@10.0.1/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:111)
java.base@10.0.1/sun.nio.ch.IOUtil.write(IOUtil.java:80)
java.base@10.0.1/sun.nio.ch.FileChannelImpl.writeInternal(FileChannelImpl.java:857)
java.base@10.0.1/sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:840)
   - locked java.lang.Object@4d372fde
app//org.h2.store.fs.FileNio.write(FilePathNio.java:79)
app//org.h2.mvstore.DataUtils.writeFully(DataUtils.java:437)
app//org.h2.mvstore.FileStore.writeFully(FileStore.java:113)
app//org.h2.mvstore.MVStore.write(MVStore.java:899)
app//org.h2.mvstore.MVStore.storeNow(MVStore.java:1282)
app//org.h2.mvstore.MVStore.store(MVStore.java:1140)
app//org.h2.mvstore.MVStore.tryCommit(MVStore.java:1085)
app//org.h2.mvstore.MVStore.beforeWrite(MVStore.java:2370)
app//org.h2.mvstore.MVMap.beforeWrite(MVMap.java:942)
app//org.h2.mvstore.MVMap.operate(MVMap.java:1707)
app//org.h2.mvstore.MVMap.put(MVMap.java:160)
app//org.h2.mvstore.MVMap.replace(MVMap.java:520)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:628)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:644)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:644)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:644)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:644)
app//org.h2.mvstore.MVMap.rewrite(MVMap.java:610)
app//org.h2.mvstore.MVStore.compactRewrite(MVStore.java:2098)
app//org.h2.mvstore.MVStore.compact(MVStore.java:1973)
app//org.h2.mvstore.MVStore.writeInBackground(MVStore.java:2699)
app//org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:3000)

java.base@10.0.1/sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:798)
app//org.h2.store.fs.FileNio.read(FilePathNio.java:74)
app//org.h2.mvstore.DataUtils.readFully(DataUtils.java:404)
app//org.h2.mvstore.FileStore.readFully(FileStore.java:98)
app//org.h2.mvstore.MVStore.readBufferForPage(MVStore.java:998)
app//org.h2.mvstore.MVStore$ChunkIdsCollector.visit(MVStore.java:1542)
app//org.h2.mvstore.Page.readChildrenPositions(Page.java:268)
app//org.h2.mvstore.MVStore$ChunkIdsCollector.visit(MVStore.java:1543)
app//org.h2.mvstore.Page$1.run(Page.java:276)
java.base@10.0.1/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
java.base@10.0.1/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base@10.0.1/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
java.base@10.0.1/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.base@10.0.1/java.lang.Thread.run(Thread.java:844)

@andreitokar
Copy link
Contributor

andreitokar commented Nov 25, 2018 •
edited

Your stack traces look normal. It is expected that compaction of 115Gb database can take a loooong time. If your test continually makes updates, databases chankes become sparsely populated and need to be compacted. One workaround is to shutdown database at some point and have SHUTDOWN_DEFRAG=TRUE option in url, which would invoke off-line compaction on shutdown. This procedure is much more efficient, than the online compaction. Another option is to have a higher threshold for automatic compaction, but MVStore "autoCompactFillRate" configuration parameter is not available directly from url when MVStore is used within H2 database (mayby it should be). The downside of this scenario that you db file would be even bigger.
In any case, there is a price to pay for massive continuous updates, and in your case it looks too high to handle in automatic fashion without big delays. It all depends on usage pattern, so without some use case at hand, it would be hard to nail down any performance issues.

@offbynull
Copy link
Author

Maybe it's possible for compaction to take place without stopping the world? Or maybe for it to only take place if the database isn't in use?

Either way, I think the periodic pauses are something I can live with. Thank you for the quick responses.

@sageserpent-open sageserpent-open mentioned this issue Jul 2, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@offbynull @andreitokar