Slow start due to large transaction log

[Carl Hasselskog]

In my application the opening of the first connection is quite slow (often >60s). After profiling it I think it the result of a large undo-log (i.e. stage RECOVERY_STAGE_UNDO in recover()). The strange thing is that I am not creating any large transactions (only use auto-commit = true). What is it that can cause the undo-log to grow so much if you're not creating any transaction yourself? One theory I have is that I have some quite large ResultSets that create temporary tables and that are not closed very often. They are usually still open when the application is closed. Can that cause the transaction-log to grow? If so, do you have any tips on how I can work around it?

Thanks!

Carl Hasselskog

[Thomas Mueller]

Hi,

Could you use the Recover tool to find out which session (=
connection) was not committed? See at the beginning of the section
"---- Transaction log ----", and look at those sessions that were not
committed.

Regards,
Thomas

> --
> You received this message because you are subscribed to the Google Groups
> "H2 Database" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/h2-database/-/qI3CjiX4ebsJ.
> To post to this group, send email to h2-da...@googlegroups.com.
> To unsubscribe from this group, send email to
> h2-database...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/h2-database?hl=en.

[Carl Hasselskog]

I think I have found it. As I suspected it is the large ResultSets that are causing the transaction-log to grow. Today I ran into another problem, which I believe is caused by the same thing.

java.lang.RuntimeException: Undo entry not written

at org.h2.message.DbException.throwInternalError(DbException.java:228)

at org.h2.store.PageLog.addUndo(PageLog.java:486)

at org.h2.store.PageStore.free(PageStore.java:1212)

at org.h2.store.PageStore.free(PageStore.java:1195)

at org.h2.index.PageDataLeaf.freeRecursive(PageDataLeaf.java:426)

at org.h2.index.PageDataNode.freeRecursive(PageDataNode.java:263)

at org.h2.index.PageDataNode.freeRecursive(PageDataNode.java:263)

at org.h2.index.PageDataIndex.removeAllRows(PageDataIndex.java:379)

at org.h2.index.PageDataIndex.truncate(PageDataIndex.java:364)

at org.h2.table.RegularTable.truncate(RegularTable.java:388)

at org.h2.result.ResultTempTable.dropTable(ResultTempTable.java:149)

at org.h2.result.ResultTempTable.close(ResultTempTable.java:139)

at org.h2.result.LocalResult.close(LocalResult.java:381)

at org.h2.jdbc.JdbcResultSet.nextRow(JdbcResultSet.java:2993)

at org.h2.jdbc.JdbcResultSet.next(JdbcResultSet.java:116)

... 15 common frames omitted

I have two questions about this:

1. What does this do? log.addUndo(pageId, null); (in PageStore.java:1212) To me it looks like setting the page-parameter to null is what is causing the exception.
2. Wouldn't it be better to just delete the ResultSet-table without undo-support? Is there any use-case when you want to undo the closing of a ResultSet?

Regards

Carl Hasselskog

> h2-database+unsubscribe@googlegroups.com.

[Bob]

How do you know which items in the transaction log were not
committed ?


On Apr 11, 3:36 pm, Thomas Mueller <thomas.tom.muel...@gmail.com>
wrote:

[Thomas Mueller]

Hi,

Do you have a reproducible test case? If possible, could you send it?

1. What does this do? log.addUndo(pageId, null); (in PageStore.java:1212)

As in the comment in the source code, "ensure the undo entry is already written". 

1. To me it looks like setting the page-parameter to null is what is causing the exception.

No, it's just a verification. 

1. Wouldn't it be better to just delete the ResultSet-table without undo-support? Is there any use-case when you want to undo the closing of a ResultSet?

I don't think that's the problem.

Regards,

Thomas

[Carl Hasselskog]

I don't the undo-support is causing the problem but doesn't it seem unnecessary to track undos for ResultSets? I will try to create a simple reproducible case.

Regards

Carl

[Carl Hasselskog]

I don't have a reproducible test-case yet but I have some more info, which I think might be related. When I'm trying to connect to the same database I now get the following error:

ERROR - FileDataBlockDB:database close org.h2.message.DbException: File corrupted while reading record: "index not found 34". Possible solution: use the recovery tool [90030-166]

at org.h2.message.DbException.get(DbException.java:169)

at org.h2.message.DbException.get(DbException.java:146)

at org.h2.store.PageStore.getPage(PageStore.java:804)

at org.h2.store.PageStore.compact(PageStore.java:696)

at org.h2.store.PageStore.compact(PageStore.java:524)

at org.h2.engine.Database.closeOpenFilesAndUnlock(Database.java:1198)

at org.h2.engine.Database.close(Database.java:1148)

at org.h2.engine.Database.removeSession(Database.java:1027)

at org.h2.engine.Session.close(Session.java:563)

at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:363)

The database has only one table so it is not unlikely that the problems are related. 

[Carl Hasselskog]

I recreated the database and now I got this error (after using it for a while).

ERROR - FileDataBlockDB:jdbc[2] exception org.h2.jdbc.JdbcSQLException: General error: "java.lang.RuntimeException: page[14103] data node table:95 entries:7 [20170, 20169, 20501, 20872, 21216, 25457, 27049, 27414] parent 0 expected 15"; SQL statement:

INSERT INTO FileDataBlocks (  filePath ,   dataBlockID,   nodeID,   relativeFileBackupTime,   absoluteFileBackupTime,   fileModificationTime,   isDirectory,   dataBlockSize ,   dataBlockVersionTimestamp ,   fileStartPosition ,   dataBlockStartPosition ,   fileDataLength,     FileChecksum,     fileIsDeleted,     fileVersionIsObsolete,     rowModificationTime,     dataBlockEncryptionKey,   dataBlockCompressionAlgorithm,   fileCompressionAlgorithm,   fileData  ) VALUES (   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?,   ?)  [50000-166]

at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)

at org.h2.message.DbException.get(DbException.java:158)

at org.h2.message.DbException.convert(DbException.java:281)

at org.h2.table.RegularTable.addRow(RegularTable.java:139)

at org.h2.command.dml.Insert.insertRows(Insert.java:124)

at org.h2.command.dml.Insert.update(Insert.java:84)

at org.h2.command.CommandContainer.update(CommandContainer.java:73)

at org.h2.command.Command.executeUpdate(Command.java:226)

at org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:181)

at com.degoo.backend.databases.FileDataBlockDB.insertFileDataBlock(FileDataBlockDB.java:357)

at com.degoo.backend.databases.FileDataBlockDB.addDataBlockToFileVersion(FileDataBlockDB.java:325)

at com.degoo.backend.databases.FileDataBlockDB.addSmallFileOrDir(FileDataBlockDB.java:287)

at com.degoo.backend.processor.streams.DataBlockInputStream.openNextFile(DataBlockInputStream.java:284)

at com.degoo.backend.processor.streams.DataBlockInputStream.read(DataBlockInputStream.java:108)

at java.io.InputStream.read(InputStream.java:171)

at SevenZip.Compression.LZ.InWindow.ReadBlock(InWindow.java:48)

at SevenZip.Compression.LZ.InWindow.MovePos(InWindow.java:101)

at SevenZip.Compression.LZ.BinTree.MovePos(BinTree.java:67)

at SevenZip.Compression.LZ.BinTree.GetMatches(BinTree.java:248)

at SevenZip.Compression.LZMA.Encoder.ReadMatchDistances(Encoder.java:433)

at SevenZip.Compression.LZMA.Encoder.GetOptimum(Encoder.java:701)

at SevenZip.Compression.LZMA.Encoder.CodeOneBlock(Encoder.java:1108)

at SevenZip.Compression.LZMA.Encoder.Code(Encoder.java:1283)

at com.degoo.backend.processor.FileEncoder.createDataBlock(FileEncoder.java:169)

at com.degoo.backend.processor.FileEncoder.createDataBlock(FileEncoder.java:134)

at com.degoo.backend.processor.FileEncoder.iterate(FileEncoder.java:82)

at com.degoo.backend.processor.scheduling.IdleRunnable.run(IdleRunnable.java:59)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)

at java.util.concurrent.FutureTask.run(FutureTask.java:166)

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

at java.lang.Thread.run(Thread.java:722)

Caused by: java.lang.RuntimeException: page[14103] data node table:95 entries:7 [20170, 20169, 20501, 20872, 21216, 25457, 27049, 27414] parent 0 expected 15

at org.h2.message.DbException.throwInternalError(DbException.java:228)

at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:239)

at org.h2.index.PageDataNode.addRowTry(PageDataNode.java:128)

at org.h2.index.PageDataIndex.addTry(PageDataIndex.java:167)

at org.h2.index.PageDataIndex.add(PageDataIndex.java:130)

at org.h2.table.RegularTable.addRow(RegularTable.java:121)

... 31 common frames omitted

[Thomas Mueller]

Hi,

This sounds like a corruption. I have a few questions:

- What is your database URL?

- Did you use LOG=0 or LOG=1? Did you read the FAQ about it?

- Did the system ever run out of disk space?

- Could you send the full stack trace of the exception including message text?

- Did you use SHUTDOWN DEFRAG or the database setting DEFRAG_ALWAYS with H2 version 1.3.159 or older?

- How many connections does your application use concurrently?

- Do you use temporary tables?

- With which version of H2 was this database created?
    You can find it out using:
    select * from information_schema.settings where name='CREATE_BUILD'
    or have a look in the SQL script created by the recover tool.

- Did the application run out of memory (once, or multiple times)?

- Do you use any settings or special features (for example cache settings,
    two phase commit, linked tables)?

- Do you use any H2-specific system properties?

- Is the application multi-threaded?

- What operating system, file system, and virtual machine
    (java -version) do you use?

- How did you start the Java process (java -Xmx... and so on)?

- Is it (or was it at some point) a networked file system?

- How big is the database (file sizes)?

- How much heap memory does the Java process have?

- Is the database usually closed normally, or is process terminated
    forcefully or the computer switched off?

- Is it possible to reproduce this problem using a fresh database
    (sometimes, or always)?

- Are there any other exceptions (maybe in the .trace.db file)?
    Could you send them please?

- Do you still have any .trace.db files, and if yes could you send them?

- Could you send the .h2.db file where this exception occurs?

Regards,
Thomas

--

You received this message because you are subscribed to the Google Groups "H2 Database" group.

To view this discussion on the web visit https://groups.google.com/d/msg/h2-database/-/ZdPWECLasewJ.

To post to this group, send email to h2-da...@googlegroups.com.

To unsubscribe from this group, send email to h2-database...@googlegroups.com.

[Carl Hasselskog]

- What is your database URL?

jdbc:h2:databases\FileDataBlockDB-FullBackupTest;TRACE_LEVEL_FILE=4;QUERY_CACHE_SIZE=2048;MAX_COMPACT_TIME=1000

- Did you use LOG=0 or LOG=1? Did you read the FAQ about it?

I haven't specified that so whatever the default is (I assume it's LOG=1?).

- Did the system ever run out of disk space?

Nope.

- Could you send the full stack trace of the exception including message text?

Sorry, I don't have the corrupt database available so I can't recreate the exception. It happened while I was running some tests, so I just recreated the db so that I could continue testing. I will make sure to save a copy of the db and the full stack trace, if it re-occurs.

- Did you use SHUTDOWN DEFRAG or the database setting DEFRAG_ALWAYS with H2 version 1.3.159 or older?

Nope.

- How many connections does your application use concurrently?

1. I also have two more H2-databases open (one connection each).

- Do you use temporary tables?

Not explicitly. Only through the large queries I mentioned.

- With which version of H2 was this database created?
    You can find it out using:
    select * from information_schema.settings where name='CREATE_BUILD'
    or have a look in the SQL script created by the recover tool.

1.3.166. However, if I remember correctly it has happened in 1.3.165 as well.

- Did the application run out of memory (once, or multiple times)?

Nope.

- Do you use any settings or special features (for example cache settings,
    two phase commit, linked tables)?

Not more stuff than specified in the connection URL.

- Do you use any H2-specific system properties?

Nope.

- Is the application multi-threaded?

Yes.

- What operating system, file system, and virtual machine
    (java -version) do you use?

Win7, NTFS. JDK 7

- How did you start the Java process (java -Xmx... and so on)?

"C:\Program Files (x86)\Java\jdk1.7.0\bin\java" -agentlib:jdwp=transport=dt_socket,address=127.0.0.1:60036,suspend=y,server=n -server -Xms16m -Xmx1024m -Djavax.net.debug=off -XX:-OmitStackTraceInFastThrow -XX:GCTimeRatio=1 -XX:AdaptiveSizeDecrementScaleFactor=1 -XX:+AggressiveOpts -Dfile.encoding=windows-1252 -classpath [lots of dependencies]  

- Is it (or was it at some point) a networked file system?

Nope

- How big is the database (file sizes)?

It differs a lot but ~500mb.

- How much heap memory does the Java process have?

1024

- Is the database usually closed normally, or is process terminated
    forcefully or the computer switched off?

 I did close it forcefully from IntelliJ a couple of time (I was running in debug-mode). Don't know if that closes the JVM without triggering shutdown-hooks and whatnot. 

- Is it possible to reproduce this problem using a fresh database
    (sometimes, or always)?

It has happened a couple of times but I haven't found a deterministic way to reproduce it yet.

- Are there any other exceptions (maybe in the .trace.db file)?
    Could you send them please?

Nope, sorry.

- Do you still have any .trace.db files, and if yes could you send them?

Nope, sorry. 

- Could you send the .h2.db file where this exception occurs?

Nope, sorry. I will make sure to save it the next time the problem occurrs.

Regards

Carl

To unsubscribe from this group, send email to h2-database+unsubscribe@googlegroups.com.