Slow recover after power failure

[BrianR]

After power failure, the first connection takes quite some time. Looking at the trace, it looks like indexes are being rebuilt (with some indexes rebuilt multiple times).

What settings can be used to reduce the amount of time to recover after reboot (smaller transaction log, etc)?

Here is an example test connection stack to recover after failure:

Profiler: top 3 stack trace(s) of 96733 ms [build-163]:
9835/27486 (35%):
at java.lang.Class.getComponentType(Native Method)
at org.h2.store.Page.insert(Page.java:109)
at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:161)
at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:100)
at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:200)
at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:105)
at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:96)
at org.h2.table.RegularTable.addRowsToIndex(RegularTable.java:327)
at org.h2.table.RegularTable.addIndex(RegularTable.java:256)
at org.h2.store.PageStore.addMeta(PageStore.java:1660)
at org.h2.store.PageStore.redo(PageStore.java:1495)
at org.h2.store.PageLog.recover(PageLog.java:319)
at org.h2.store.PageStore.recover(PageStore.java:1358)
at org.h2.store.PageStore.openExisting(PageStore.java:355)
at org.h2.store.PageStore.open(PageStore.java:279)
at org.h2.engine.Database.getPageStore(Database.java:2118)
at org.h2.engine.Database.open(Database.java:577)
at org.h2.engine.Database.openDatabase(Database.java:222)
at org.h2.engine.Database.<init>(Database.java:217)
at org.h2.engine.Engine.openSession(Engine.java:56)
at org.h2.engine.Engine.openSession(Engine.java:159)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:138)
at org.h2.engine.Engine.createSession(Engine.java:121)
at org.h2.engine.Engine.createSession(Engine.java:28)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:305)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:110)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:94)
at org.h2.Driver.connect(Driver.java:72)
at org.h2.server.web.WebServer.getConnection(WebServer.java:644)
at org.h2.server.web.WebApp.test(WebApp.java:839)
at org.h2.server.web.WebApp.process(WebApp.java:215)
at org.h2.server.web.WebApp.processRequest(WebApp.java:164)
2326/27486 (8%):
at org.h2.index.BaseIndex.compareRows(BaseIndex.java:171)
at org.h2.table.RegularTable$1.compare(RegularTable.java:323)
at org.h2.table.RegularTable$1.compare(RegularTable.java:322)
at java.util.Arrays.mergeSort(Unknown Source)
at java.util.Arrays.sort(Unknown Source)
at java.util.Collections.sort(Unknown Source)
at org.h2.table.RegularTable.addRowsToIndex(RegularTable.java:321)
at org.h2.table.RegularTable.addIndex(RegularTable.java:256)
at org.h2.store.PageStore.addMeta(PageStore.java:1660)
at org.h2.store.PageStore.redo(PageStore.java:1495)
at org.h2.store.PageLog.recover(PageLog.java:319)
at org.h2.store.PageStore.recover(PageStore.java:1358)
at org.h2.store.PageStore.openExisting(PageStore.java:355)
at org.h2.store.PageStore.open(PageStore.java:279)
at org.h2.engine.Database.getPageStore(Database.java:2118)
at org.h2.engine.Database.open(Database.java:577)
at org.h2.engine.Database.openDatabase(Database.java:222)
at org.h2.engine.Database.<init>(Database.java:217)
at org.h2.engine.Engine.openSession(Engine.java:56)
at org.h2.engine.Engine.openSession(Engine.java:159)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:138)
at org.h2.engine.Engine.createSession(Engine.java:121)
at org.h2.engine.Engine.createSession(Engine.java:28)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:305)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:110)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:94)
at org.h2.Driver.connect(Driver.java:72)
at org.h2.server.web.WebServer.getConnection(WebServer.java:644)
at org.h2.server.web.WebApp.test(WebApp.java:839)
at org.h2.server.web.WebApp.process(WebApp.java:215)
at org.h2.server.web.WebApp.processRequest(WebApp.java:164)
at org.h2.server.web.WebThread.process(WebThread.java:137)
1852/27486 (6%):
at org.h2.table.Table.compareTypeSave(Table.java:1035)
at org.h2.index.BaseIndex.compareValues(BaseIndex.java:244)
at org.h2.index.BaseIndex.compareRows(BaseIndex.java:176)
at org.h2.table.RegularTable$1.compare(RegularTable.java:323)
at org.h2.table.RegularTable$1.compare(RegularTable.java:322)
at java.util.Arrays.mergeSort(Unknown Source)
at java.util.Arrays.sort(Unknown Source)
at java.util.Collections.sort(Unknown Source)
at org.h2.table.RegularTable.addRowsToIndex(RegularTable.java:321)
at org.h2.table.RegularTable.addIndex(RegularTable.java:256)
at org.h2.store.PageStore.addMeta(PageStore.java:1660)
at org.h2.store.PageStore.redo(PageStore.java:1495)
at org.h2.store.PageLog.recover(PageLog.java:319)
at org.h2.store.PageStore.recover(PageStore.java:1358)
at org.h2.store.PageStore.openExisting(PageStore.java:355)
at org.h2.store.PageStore.open(PageStore.java:279)
at org.h2.engine.Database.getPageStore(Database.java:2118)
at org.h2.engine.Database.open(Database.java:577)
at org.h2.engine.Database.openDatabase(Database.java:222)
at org.h2.engine.Database.<init>(Database.java:217)
at org.h2.engine.Engine.openSession(Engine.java:56)
at org.h2.engine.Engine.openSession(Engine.java:159)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:138)
at org.h2.engine.Engine.createSession(Engine.java:121)
at org.h2.engine.Engine.createSession(Engine.java:28)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:305)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:110)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:94)
at org.h2.Driver.connect(Driver.java:72)
at org.h2.server.web.WebServer.getConnection(WebServer.java:644)
at org.h2.server.web.WebApp.test(WebApp.java:839)
at org.h2.server.web.WebApp.process(WebApp.java:215)
packages:
53%: org.h2.store
17%: org.h2.index
15%: org.h2.table
.
Profiler: top 3 stack trace(s) of 598 ms [build-163]:
70/201 (34%):
at java.io.FileDescriptor.sync(Native Method)
at org.h2.store.fs.FileDisk.force(FilePathDisk.java:387)
at org.h2.store.FileStore.sync(FileStore.java:413)
at org.h2.store.PageStore.writeVariableHeader(PageStore.java:940)
at org.h2.store.PageStore.setLogFirstPage(PageStore.java:934)
at org.h2.store.PageLog.removeUntil(PageLog.java:702)
at org.h2.store.PageStore.checkpoint(PageStore.java:427)
at org.h2.store.PageStore.compact(PageStore.java:597)
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:365)
at org.h2.util.JdbcUtils.closeSilently(JdbcUtils.java:79)
at org.h2.server.web.WebApp.test(WebApp.java:847)
at org.h2.server.web.WebApp.process(WebApp.java:215)
at org.h2.server.web.WebApp.processRequest(WebApp.java:164)
at org.h2.server.web.WebThread.process(WebThread.java:137)
at org.h2.server.web.WebThread.run(WebThread.java:93)
at java.lang.Thread.run(Unknown Source)
56/201 (27%):
at java.io.FileDescriptor.sync(Native Method)
at org.h2.store.fs.FileDisk.force(FilePathDisk.java:387)
at org.h2.store.FileStore.sync(FileStore.java:413)
at org.h2.store.PageStore.writeVariableHeader(PageStore.java:940)
at org.h2.store.PageStore.setLogFirstPage(PageStore.java:934)
at org.h2.store.PageStore.compact(PageStore.java:610)
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:365)
at org.h2.util.JdbcUtils.closeSilently(JdbcUtils.java:79)
at org.h2.server.web.WebApp.test(WebApp.java:847)
at org.h2.server.web.WebApp.process(WebApp.java:215)
at org.h2.server.web.WebApp.processRequest(WebApp.java:164)
at org.h2.server.web.WebThread.process(WebThread.java:137)
at org.h2.server.web.WebThread.run(WebThread.java:93)
at java.lang.Thread.run(Unknown Source)
25/201 (12%):
at java.io.FileDescriptor.sync(Native Method)
at org.h2.store.fs.FileDisk.force(FilePathDisk.java:387)
at org.h2.store.FileStore.sync(FileStore.java:413)
at org.h2.store.PageStore.writeVariableHeader(PageStore.java:940)
at org.h2.store.PageStore.setLogFirstPage(PageStore.java:934)
at org.h2.store.PageLog.openForWriting(PageLog.java:188)
at org.h2.store.PageStore.compact(PageStore.java:489)
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:365)
at org.h2.util.JdbcUtils.closeSilently(JdbcUtils.java:79)
at org.h2.server.web.WebApp.test(WebApp.java:847)
at org.h2.server.web.WebApp.process(WebApp.java:215)
at org.h2.server.web.WebApp.processRequest(WebApp.java:164)
at org.h2.server.web.WebThread.process(WebThread.java:137)
at org.h2.server.web.WebThread.run(WebThread.java:93)
at java.lang.Thread.run(Unknown Source)
packages:
90%: org.h2.store.fs
4%: org.h2.util
2%: org.h2.store 

[andreis]

> What settings can be used to reduce the amount of time to recover after
> reboot (smaller transaction log, etc)?

Try to issue 'CHECKPOINT' just after 'CREATE INDEX'. That helped me.

[Thomas Mueller]

Hi,

After power failure, the first connection takes quite some time.

How much time does it take exactly?

 

 Looking at the trace, it looks like indexes are being rebuilt (with some indexes rebuilt multiple times).

Yes, it looks like an index is re-built. Why do you think some indexes are rebuilt multiple times?

 

What settings can be used to reduce the amount of time to recover after reboot (smaller transaction log, etc)?

I wonder if there were large, open transactions at the time of the power failure. Do you have a reproducible test case?

Regards,

Thomas

[BrianR]

For performance reasons, our client was doing the following for a large insert: a constraint was being removed, insert the data, then constraint added again. 

On recovery, these steps were being repeated many times when replaying the transaction log. The startup was taking over 11 minutes on a small CPU. We are changing the client to not need the constraint and therefore not add and remove it. Now, the recovery time is much better.

But, I'm still looking at ways (h2 options or best practices) to keep the recovery time as low as possible after power failure

[Thomas Mueller]

Hi,

For performance reasons, our client was doing the following for a large insert: a constraint was being removed, insert the data, then constraint added again. 

I wonder if disabling and then re-adding the constraint really improved performance, if it caused an index to be created / dropped. I would think recovery is as fast / as slow as the time it took while the program was running.

On recovery, these steps were being repeated many times when replaying the transaction log. The startup was taking over 11 minutes on a small CPU. We are changing the client to not need the constraint and therefore not add and remove it. Now, the recovery time is much better.

OK.

 

But, I'm still looking at ways (h2 options or best practices) to keep the recovery time as low as possible after power failure.

I would try to avoid adding / creating the same index over and over again at runtime (but this isn't really related to recovery).

To speed up recovery, using a smaller log size might help (max_log_size).

Regards,

Thomas