log file deletion issue in emebedded mode
16 views
Skip to first unread message
Dhruv Patel
Feb 12, 2008, 10:16:31 AM2/12/08
to H2 Database
hi,
i am running application on JRE 1.5.13 under Windows XP SP2.
using latest H2 version 1.0.66.
i am using H2 in embedded mode opening and closing connections as
needed.
Connection String :
jdbc:h2:file:DATABASE_PATH;IGNORECASE=TRUE;LOG=0;FILE_LOCK=NO;MVCC=TRUE
i have monitored creation and deletion of temporary trace and log
files while opening and closing.
but suddenly after some time i am getting Exception
org.h2.jdbc.JdbcSQLException: Cannot delete file C:\D\Codes\Java
\ASLiteH2\workbe
nch\system\systemdb.36.log.db [90025-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.getSQLException(Message.java:93)
at org.h2.message.Message.getSQLException(Message.java:71)
at org.h2.store.fs.FileSystemDisk.delete(FileSystemDisk.java:
129)
at org.h2.util.FileUtils.delete(FileUtils.java:181)
at org.h2.log.LogFile.close(LogFile.java:393)
at org.h2.log.LogSystem.closeOldFile(LogSystem.java:225)
at org.h2.log.LogSystem.flushAndCloseUnused(LogSystem.java:
119)
at org.h2.log.LogSystem.checkpoint(LogSystem.java:411)
at org.h2.log.LogSystem.recover(LogSystem.java:218)
at org.h2.engine.Database.open(Database.java:447)
at org.h2.engine.Database.<init>(Database.java:193)
at org.h2.engine.Engine.openSession(Engine.java:52)
at org.h2.engine.Engine.getSession(Engine.java:100)
at org.h2.engine.Session.createSession(Session.java:180)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:926)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:907)
at org.h2.Driver.connect(Driver.java:52)
at java.sql.DriverManager.getConnection(Unknown Source)
at java.sql.DriverManager.getConnection(Unknown Source)
which shut down my application.
same code is running fine without any problem for starting runs.
it is observed that when opening and closing connection repeatedly in
embedded mode,
above problem can be observed.
my personal understanding is, log file could not be closed because the
file is still open in some other thread in H2. hence file deletion
code attempts deletion operation repeatedly for some time taking
intermediate pauses.
so this is more of thread race condition inside H2, as i believe.
how this problem can be fixed???
what should be the best connection string to be used for embedded
mode?
Regards
Dhruv Patel
i am running application on JRE 1.5.13 under Windows XP SP2.
using latest H2 version 1.0.66.
i am using H2 in embedded mode opening and closing connections as
needed.
Connection String :
jdbc:h2:file:DATABASE_PATH;IGNORECASE=TRUE;LOG=0;FILE_LOCK=NO;MVCC=TRUE
i have monitored creation and deletion of temporary trace and log
files while opening and closing.
but suddenly after some time i am getting Exception
org.h2.jdbc.JdbcSQLException: Cannot delete file C:\D\Codes\Java
\ASLiteH2\workbe
nch\system\systemdb.36.log.db [90025-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.getSQLException(Message.java:93)
at org.h2.message.Message.getSQLException(Message.java:71)
at org.h2.store.fs.FileSystemDisk.delete(FileSystemDisk.java:
129)
at org.h2.util.FileUtils.delete(FileUtils.java:181)
at org.h2.log.LogFile.close(LogFile.java:393)
at org.h2.log.LogSystem.closeOldFile(LogSystem.java:225)
at org.h2.log.LogSystem.flushAndCloseUnused(LogSystem.java:
119)
at org.h2.log.LogSystem.checkpoint(LogSystem.java:411)
at org.h2.log.LogSystem.recover(LogSystem.java:218)
at org.h2.engine.Database.open(Database.java:447)
at org.h2.engine.Database.<init>(Database.java:193)
at org.h2.engine.Engine.openSession(Engine.java:52)
at org.h2.engine.Engine.getSession(Engine.java:100)
at org.h2.engine.Session.createSession(Session.java:180)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:926)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:907)
at org.h2.Driver.connect(Driver.java:52)
at java.sql.DriverManager.getConnection(Unknown Source)
at java.sql.DriverManager.getConnection(Unknown Source)
which shut down my application.
same code is running fine without any problem for starting runs.
it is observed that when opening and closing connection repeatedly in
embedded mode,
above problem can be observed.
my personal understanding is, log file could not be closed because the
file is still open in some other thread in H2. hence file deletion
code attempts deletion operation repeatedly for some time taking
intermediate pauses.
so this is more of thread race condition inside H2, as i believe.
how this problem can be fixed???
what should be the best connection string to be used for embedded
mode?
Regards
Dhruv Patel
Thomas Mueller
Feb 13, 2008, 2:56:47 PM2/13/08
to h2-da...@googlegroups.com
Hi,
I tried to reproduce this problem but couldn't so far. Could you create a test case? I have tried this:
public static void main(String[] a) throws Exception {
DeleteDbFiles.execute("data", null, true);
Class.forName("org.h2.Driver");
while(true) {
Connection conn1 = DriverManager.getConnection("jdbc:h2:data/test;LOG=0;FILE_LOCK=NO;MVCC=TRUE", "sa", "sa");
// jdbc:h2:file:DATABASE_PATH;IGNORECASE=TRUE;LOG=0;FILE_LOCK=NO;MVCC=TRUE
Statement stat = conn1.createStatement();
stat.execute("DROP TABLE IF EXISTS TEST");
stat.execute("CREATE TABLE TEST()");
stat.execute("CHECKPOINT");
stat.execute("DROP TABLE IF EXISTS TEST");
stat.execute("CREATE TABLE TEST()");
stat.execute("SHUTDOWN IMMEDIATELY");
// conn1.close();
}
}
I tried various URLs, and sometimes with SHUTDOWN IMMEDIATELY and sometimes by closing the database.
Regards,
Thomas
I tried to reproduce this problem but couldn't so far. Could you create a test case? I have tried this:
public static void main(String[] a) throws Exception {
DeleteDbFiles.execute("data", null, true);
Class.forName("org.h2.Driver");
while(true) {
Connection conn1 = DriverManager.getConnection("jdbc:h2:data/test;LOG=0;FILE_LOCK=NO;MVCC=TRUE", "sa", "sa");
// jdbc:h2:file:DATABASE_PATH;IGNORECASE=TRUE;LOG=0;FILE_LOCK=NO;MVCC=TRUE
Statement stat = conn1.createStatement();
stat.execute("DROP TABLE IF EXISTS TEST");
stat.execute("CREATE TABLE TEST()");
stat.execute("CHECKPOINT");
stat.execute("DROP TABLE IF EXISTS TEST");
stat.execute("CREATE TABLE TEST()");
stat.execute("SHUTDOWN IMMEDIATELY");
// conn1.close();
}
}
I tried various URLs, and sometimes with SHUTDOWN IMMEDIATELY and sometimes by closing the database.
Regards,
Thomas
dkerrigan
Mar 18, 2008, 1:50:23 PM3/18/08
to H2 Database
Thomas,
I have also encountered this problem very recently. Below is some
code and a few items from our logs. Using H2 version 1.65 and jre
1.6u3. Unfortunately this did not halt our application but instead
filled up our logs in hopes we'd be able to troubleshoot the error
later. This particular piece of code runs millions of times an hour
for months at a time so repeating the error might be unrealistic.
The code that generated this error looked somewhat like this:
private static final String DELETE_QUERY =
"DELETE FROM MESSAGE_QUEUE WHERE ID = ?";
PreparedStatement deleteStmt = conn.prepareStatement(
DELETE_QUERY);
for (int i = 0; i < counts.length; ++i) {
if (counts[i] != Statement.EXECUTE_FAILED) {
deleteStmt.setLong(1, keys[i]);
deleteStmt.executeUpdate(); // Line 288
++count;
}
}
And a small sampling of logs including the first exception -
21:27:09 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-6] - processByBatch failed
org.h2.jdbc.JdbcSQLException: Cannot delete file E:\xxxx\xxxParser\data
\queue.2916.log.db [90025-66]
at org.h2.store.DiskFile.removeRecord(DiskFile.java:755)
at org.h2.store.Storage.removeRecord(Storage.java:154)
at org.h2.index.ScanIndex.remove(ScanIndex.java:160)
at org.h2.table.TableData.removeRow(TableData.java:290)
at org.h2.command.dml.Delete.update(Delete.java:67)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
288)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: rowCount
expected 10 got 9 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: rowCount expected 10 got 9
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.table.TableData.addRow(TableData.java:102)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: rowCount
expected 10 got 9 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: rowCount expected 10 got 9
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.table.TableData.addRow(TableData.java:102)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-1] - processByBatch failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: File ID
mismatch got=0 expected=23 pos=261 true org.h2.store.DiskFile:E:\xxxx
\xxxParser\data\queue.data.db blockCount:0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.command.Command.executeQueryLocal(Command.java:120)
at org.h2.command.Command.executeQuery(Command.java:106)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
89)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
250)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: File ID mismatch got=0 expected=23 pos=261
true org.h2.store.DiskFile:E:\xxxx\xxxParser\data\queue.data.db
blockCount:0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.store.DiskFile.getRecord(DiskFile.java:456)
at org.h2.store.Storage.getRecord(Storage.java:65)
at org.h2.index.ScanIndex.getRow(ScanIndex.java:94)
at org.h2.table.TableData.getRow(TableData.java:85)
at org.h2.index.BtreeIndex.getRow(BtreeIndex.java:266)
at org.h2.index.BtreeCursor.get(BtreeCursor.java:65)
at org.h2.table.TableFilter.getValue(TableFilter.java:550)
at org.h2.expression.ExpressionColumn.getValue(ExpressionColumn.java:
163)
at org.h2.command.dml.Select.queryFlat(Select.java:329)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:386)
at org.h2.command.dml.Query.query(Query.java:227)
at org.h2.command.CommandContainer.query(CommandContainer.java:77)
at org.h2.command.Command.executeQueryLocal(Command.java:118)
... 10 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: try to
add a record twice i=0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: try to add a record twice i=0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.util.CacheLRU.put(CacheLRU.java:51)
at org.h2.store.DiskFile.addRecord(DiskFile.java:768)
at org.h2.store.Storage.addRecord(Storage.java:141)
at org.h2.index.ScanIndex.add(ScanIndex.java:111)
at org.h2.table.TableData.addRow(TableData.java:97)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-6] - processByBatch failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: File ID
mismatch got=0 expected=23 pos=261 true org.h2.store.DiskFile:E:\xxxx
\xxxParser\data\queue.data.db blockCount:0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.command.Command.executeQueryLocal(Command.java:120)
at org.h2.command.Command.executeQuery(Command.java:106)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
89)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
250)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: File ID mismatch got=0 expected=23 pos=261
true org.h2.store.DiskFile:E:\xxxx\xxxParser\data\queue.data.db
blockCount:0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.store.DiskFile.getRecord(DiskFile.java:456)
at org.h2.store.Storage.getRecord(Storage.java:65)
at org.h2.index.ScanIndex.getRow(ScanIndex.java:94)
at org.h2.table.TableData.getRow(TableData.java:85)
at org.h2.index.BtreeIndex.getRow(BtreeIndex.java:266)
at org.h2.index.BtreeCursor.get(BtreeCursor.java:65)
at org.h2.table.TableFilter.getValue(TableFilter.java:550)
at org.h2.expression.ExpressionColumn.getValue(ExpressionColumn.java:
163)
at org.h2.command.dml.Select.queryFlat(Select.java:329)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:386)
at org.h2.command.dml.Query.query(Query.java:227)
at org.h2.command.CommandContainer.query(CommandContainer.java:77)
at org.h2.command.Command.executeQueryLocal(Command.java:118)
... 10 more
Regards,
Dan
I have also encountered this problem very recently. Below is some
code and a few items from our logs. Using H2 version 1.65 and jre
1.6u3. Unfortunately this did not halt our application but instead
filled up our logs in hopes we'd be able to troubleshoot the error
later. This particular piece of code runs millions of times an hour
for months at a time so repeating the error might be unrealistic.
The code that generated this error looked somewhat like this:
private static final String DELETE_QUERY =
"DELETE FROM MESSAGE_QUEUE WHERE ID = ?";
PreparedStatement deleteStmt = conn.prepareStatement(
DELETE_QUERY);
for (int i = 0; i < counts.length; ++i) {
if (counts[i] != Statement.EXECUTE_FAILED) {
deleteStmt.setLong(1, keys[i]);
deleteStmt.executeUpdate(); // Line 288
++count;
}
}
And a small sampling of logs including the first exception -
21:27:09 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-6] - processByBatch failed
org.h2.jdbc.JdbcSQLException: Cannot delete file E:\xxxx\xxxParser\data
\queue.2916.log.db [90025-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.getSQLException(Message.java:93)
at org.h2.message.Message.getSQLException(Message.java:71)
at org.h2.store.fs.FileSystemDisk.delete(FileSystemDisk.java:129)
at org.h2.util.FileUtils.delete(FileUtils.java:181)
at org.h2.log.LogFile.close(LogFile.java:393)
at org.h2.log.LogSystem.closeOldFile(LogSystem.java:225)
at org.h2.log.LogSystem.flushAndCloseUnused(LogSystem.java:119)
at org.h2.log.LogSystem.checkpoint(LogSystem.java:411)
at org.h2.log.LogSystem.add(LogSystem.java:398)
at org.h2.message.Message.getSQLException(Message.java:93)
at org.h2.message.Message.getSQLException(Message.java:71)
at org.h2.store.fs.FileSystemDisk.delete(FileSystemDisk.java:129)
at org.h2.util.FileUtils.delete(FileUtils.java:181)
at org.h2.log.LogFile.close(LogFile.java:393)
at org.h2.log.LogSystem.closeOldFile(LogSystem.java:225)
at org.h2.log.LogSystem.flushAndCloseUnused(LogSystem.java:119)
at org.h2.log.LogSystem.checkpoint(LogSystem.java:411)
at org.h2.store.DiskFile.removeRecord(DiskFile.java:755)
at org.h2.store.Storage.removeRecord(Storage.java:154)
at org.h2.index.ScanIndex.remove(ScanIndex.java:160)
at org.h2.table.TableData.removeRow(TableData.java:290)
at org.h2.command.dml.Delete.update(Delete.java:67)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
288)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: rowCount
expected 10 got 9 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: rowCount expected 10 got 9
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.table.TableData.addRow(TableData.java:102)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: rowCount
expected 10 got 9 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: rowCount expected 10 got 9
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.table.TableData.addRow(TableData.java:102)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-1] - processByBatch failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: File ID
mismatch got=0 expected=23 pos=261 true org.h2.store.DiskFile:E:\xxxx
\xxxParser\data\queue.data.db blockCount:0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.command.Command.executeQueryLocal(Command.java:120)
at org.h2.command.Command.executeQuery(Command.java:106)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
89)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
250)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: File ID mismatch got=0 expected=23 pos=261
true org.h2.store.DiskFile:E:\xxxx\xxxParser\data\queue.data.db
blockCount:0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.store.DiskFile.getRecord(DiskFile.java:456)
at org.h2.store.Storage.getRecord(Storage.java:65)
at org.h2.index.ScanIndex.getRow(ScanIndex.java:94)
at org.h2.table.TableData.getRow(TableData.java:85)
at org.h2.index.BtreeIndex.getRow(BtreeIndex.java:266)
at org.h2.index.BtreeCursor.get(BtreeCursor.java:65)
at org.h2.table.TableFilter.getValue(TableFilter.java:550)
at org.h2.expression.ExpressionColumn.getValue(ExpressionColumn.java:
163)
at org.h2.command.dml.Select.queryFlat(Select.java:329)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:386)
at org.h2.command.dml.Query.query(Query.java:227)
at org.h2.command.CommandContainer.query(CommandContainer.java:77)
at org.h2.command.Command.executeQueryLocal(Command.java:118)
... 10 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Inbound Dispatcher
Thread-47] - Enqueue failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: try to
add a record twice i=0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.table.TableData.addRow(TableData.java:129)
at org.h2.command.dml.Insert.update(Insert.java:88)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:171)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:
127)
at
org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:
116)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.enqueue(EmbeddedJdbcStatementQueue.java:
212)
at
xxx.xxxx.xxxx.parser.InboundDispatcher.enqueueMessage(InboundDispatcher.java:
290)
at
xxx.xxxx.xxxx.parser.ClusteredInboundDispatcher.enqueueMessage(ClusteredInboundDispatcher.java:
62)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.processMessage(InboundDispatcher.java:465)
at xxx.xxxx.xxxx.parser.InboundDispatcher
$Worker.run(InboundDispatcher.java:431)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: try to add a record twice i=0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.util.CacheLRU.put(CacheLRU.java:51)
at org.h2.store.DiskFile.addRecord(DiskFile.java:768)
at org.h2.store.Storage.addRecord(Storage.java:141)
at org.h2.index.ScanIndex.add(ScanIndex.java:111)
at org.h2.table.TableData.addRow(TableData.java:97)
... 13 more
21:27:10 ERROR [EmbeddedJdbcStatementQueue:Outbound Dispatcher
Thread-6] - processByBatch failed
org.h2.jdbc.JdbcSQLException: General error: java.lang.Error: File ID
mismatch got=0 expected=23 pos=261 true org.h2.store.DiskFile:E:\xxxx
\xxxParser\data\queue.data.db blockCount:0 [50000-66]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.convert(Message.java:174)
at org.h2.command.Command.executeQueryLocal(Command.java:120)
at org.h2.command.Command.executeQuery(Command.java:106)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
89)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.doBatch(EmbeddedJdbcStatementQueue.java:
250)
at
xxx.xxxx.xxxx.parser.queue.jdbc.EmbeddedJdbcStatementQueue.processByHash(EmbeddedJdbcStatementQueue.java:
227)
at
xxx.xxxx.xxxx.parser.OutboundDispatcher.handleStatement(OutboundDispatcher.java:
185)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.processBoundry(OutboundDispatcher.java:255)
at xxx.xxxx.xxxx.parser.OutboundDispatcher
$Worker.run(OutboundDispatcher.java:227)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.Error: File ID mismatch got=0 expected=23 pos=261
true org.h2.store.DiskFile:E:\xxxx\xxxParser\data\queue.data.db
blockCount:0
at org.h2.message.Message.getInternalError(Message.java:126)
at org.h2.store.DiskFile.getRecord(DiskFile.java:456)
at org.h2.store.Storage.getRecord(Storage.java:65)
at org.h2.index.ScanIndex.getRow(ScanIndex.java:94)
at org.h2.table.TableData.getRow(TableData.java:85)
at org.h2.index.BtreeIndex.getRow(BtreeIndex.java:266)
at org.h2.index.BtreeCursor.get(BtreeCursor.java:65)
at org.h2.table.TableFilter.getValue(TableFilter.java:550)
at org.h2.expression.ExpressionColumn.getValue(ExpressionColumn.java:
163)
at org.h2.command.dml.Select.queryFlat(Select.java:329)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:386)
at org.h2.command.dml.Query.query(Query.java:227)
at org.h2.command.CommandContainer.query(CommandContainer.java:77)
at org.h2.command.Command.executeQueryLocal(Command.java:118)
... 10 more
Regards,
Dan
Thomas Mueller
Mar 20, 2008, 2:10:24 PM3/20/08
to h2-da...@googlegroups.com
Hi,
> repeating the error might be unrealistic.
Maybe the problem can be reproduced easier. The checkpoint code is
only executed if the log file becomes too big, the by default log file
size is quite high. There are two ways to call checkpoint more often:
by calling it directly (execute "CHECKPOINT"), or by setting the log
file size lower (append ;MAX_LOG_SIZE=1 to the database URL).
Could you do that and run you test again?
Also I like to better understand what the test does. Could you explain
it a bit? I also have a list of questions, please answer them if you
have time:
- What is your database URL?
- What version H2 are you using?
- Did you use multiple connections?
- Do you use any settings or special features (for example, the setting
LOG=0, or two phase commit, linked tables, cache settings)?
- Is the application multi-threaded?
- On what operating system, file system, and virtual machine (java -version)?
- How big is the database?
- Are there any other exceptions (maybe in the .trace.db file)?
Could you send them to me please?
Thanks a lot for your help!
Regards,
Thomas
dkerrigan
Mar 21, 2008, 9:43:25 AM3/21/08
to H2 Database
Thomas - I've inlined my answers below:
Could you do that and run you test again?
Also I like to better understand what the test does. Could you
explain
it a bit? I also have a list of questions, please answer them if you
have time:
I will prepare a test that mirrors what we do with our database and
send it along when it's ready. We have tests but not that really
mirror this situation. We have never seen this before and is a recent
development. It occured in our production environment.
The flow of the app goes something like this:
Our database table is set up with an auto-incrementing id, a
varchar(2048) and an integer hash from 0 to 99. The purpose of the
hash is to prevent collision between outgoing workers.
One incoming thread receives messages and inserts them into the table
with the sequentially increased hash.
A pool of outgoing threads, which are assigned a range of hashes,
selects out of the table between the max and min of their
hash range with a limit of 500 (or some arbitrary limit) and prepares
a batch to insert into a back end (SQL Server).
The results of the batch insert into the back end are iterated
through. Results which are not an error are deleted from the table.
- What is your database URL?
jdbc:h2:file:[DriveLetter]:/XXXX/XXXParser/data/
queue;LOCK_MODE=0;FILE_LOCK=SOCKET
- What version H2 are you using?
1.65
- Did you use multiple connections?
No
- Do you use any settings or special features (for example, the
setting
LOG=0, or two phase commit, linked tables, cache settings)?
System.setProperty("h2.redoBufferSize", Integer.toString(1024 *
1024));
We have experimented with a larger cache (we do lots of deletes) and
LOG=2 (for faster recovery on failure) but they are not currently in
use.
- Is the application multi-threaded?
Yes
- On what operating system, file system, and virtual machine (java -
version)?
OS: Windows 2003 R2, Enterprise x64 Edition, SP2
File System: NTFS
JRE: 32-bit
java version "1.6.0_02"
Java(TM) SE Runtime Environment (build 1.6.0_02-b06)
Java HotSpot(TM) Client VM (build 1.6.0_02-b06, mixed mode)
- How big is the database?
This varies somewhat. We use the database as an intermedate queue for
when the application is not able to commit to a back end database. On
average though, the database sees 500-600 inserts per second and as
many selects and deletes as possible. I don't know how big the
database is because it was accidentally deleted. We have seen
databases as large as 30 million+ records and file sizes over 30GB but
on average the data directory might be under 5 gigs and the average
row count is between 0 and 550.
- Are there any other exceptions (maybe in the .trace.db file)?
Could you send them to me please?
Unfortunately the analyst responding deleted our data directory
instead of copying it to a safe location to get the application
running normally again. If it happens again I should be able to get
you a .trace.db file since we use the default tracing.
Thanks for all your help,
Dan
Could you do that and run you test again?
Also I like to better understand what the test does. Could you
explain
it a bit? I also have a list of questions, please answer them if you
have time:
send it along when it's ready. We have tests but not that really
mirror this situation. We have never seen this before and is a recent
development. It occured in our production environment.
The flow of the app goes something like this:
Our database table is set up with an auto-incrementing id, a
varchar(2048) and an integer hash from 0 to 99. The purpose of the
hash is to prevent collision between outgoing workers.
One incoming thread receives messages and inserts them into the table
with the sequentially increased hash.
A pool of outgoing threads, which are assigned a range of hashes,
selects out of the table between the max and min of their
hash range with a limit of 500 (or some arbitrary limit) and prepares
a batch to insert into a back end (SQL Server).
The results of the batch insert into the back end are iterated
through. Results which are not an error are deleted from the table.
- What is your database URL?
queue;LOCK_MODE=0;FILE_LOCK=SOCKET
- What version H2 are you using?
- Did you use multiple connections?
- Do you use any settings or special features (for example, the
setting
LOG=0, or two phase commit, linked tables, cache settings)?
1024));
We have experimented with a larger cache (we do lots of deletes) and
LOG=2 (for faster recovery on failure) but they are not currently in
use.
- Is the application multi-threaded?
- On what operating system, file system, and virtual machine (java -
version)?
File System: NTFS
JRE: 32-bit
java version "1.6.0_02"
Java(TM) SE Runtime Environment (build 1.6.0_02-b06)
Java HotSpot(TM) Client VM (build 1.6.0_02-b06, mixed mode)
- How big is the database?
when the application is not able to commit to a back end database. On
average though, the database sees 500-600 inserts per second and as
many selects and deletes as possible. I don't know how big the
database is because it was accidentally deleted. We have seen
databases as large as 30 million+ records and file sizes over 30GB but
on average the data directory might be under 5 gigs and the average
row count is between 0 and 550.
- Are there any other exceptions (maybe in the .trace.db file)?
Could you send them to me please?
instead of copying it to a safe location to get the application
running normally again. If it happens again I should be able to get
you a .trace.db file since we use the default tracing.
Thanks for all your help,
Dan
Thomas Mueller
Mar 25, 2008, 4:07:24 PM3/25/08
to h2-da...@googlegroups.com
Hi,
While testing with very small log file sizes I did find two bugs. This
will be solved in the next release. However the problem was not 'could
not delete log file' - this is something I still can't reproduce
unfortunately. Maybe you can reproduce the problem easier when using
MAX_LOG_SIZE=1. It would be really great to have a reproduceable test
case.
Regards,
Thomas
Reply all
Reply to author
Forward
0 new messages