DB closing is extremally slow

[wburzyns]

Hi devs,

I've got a H2 (created with h2-1.3.153) database with two tables. Each
table is created as follows: "CREATE TABLE (ID INTEGER PRIMARY KEY
AUTO_INCREMENT, CONTENT BLOB NOT NULL, DESCRIPTION VARCHAR NOT NULL,
STAMP BIGINT DEFAULT NEXT VALUE FOR GLOBAL_STAMP_SEQUENCE)". Both blob
& varchar aren't very big: blob is around 1 kB, varchar is a few
hundred characters. The row count in the two tables is as follows: 1
205 050, 4 660 558. The total size of the DB on disk is over 7 GB. I
use the following URL to create/connect the DB:
'jdbc:h2:split:my_path;PAGE_SIZE=1024'. There is only one connection
to the DB.

The problem is that the DB closing time is extremally high: for the
first time it takes over 300 seconds on a decent PC (Intel E6600, 2 GB
RAM) under WinXP! Consecutive opens/closes take over 40 seconds. The
AV scanner is off. During that process the CPU usage is rather low
(approx. 15%) and so is the I/O throughput (no more than a few
hundreds kB/s; it jumps to more than 10 MB/s for a few seconds just
before finish).

I tried adding 'MAX_COMPACT_COUNT=0;PAGE_STORE_TRIM=false' to the URL
but this hasn't helped a bit. At the moment I'm not sure if 'SHUTDOWN
IMMEDIATELY' is a viable option to me as it causes my testcases to
fail (I inspected them - they look fine). The same behaviour can be
observed using the H2 cosole: connecting and then disconnecting
immediately is ugly slow.

Of course I'll try to solve the problem on my own but if any of you
can drop me an ad hoc idea what should I try I'd be grateful.


Regards,
wburzyns

[Thomas Mueller]

Hi,

> 'jdbc:h2:split:my_path;PAGE_SIZE=1024'

Why do you split the database, and why do you use a different page size?

> During that process the CPU usage is rather low
> (approx. 15%) and so is the I/O throughput (no more than a few
> hundreds kB/s; it jumps to more than 10 MB/s for a few seconds just
> before finish).

Could you run the profiling tool to find out what exactly is going on
at that time? See
http://h2database.com/html/performance.html#application_profiling -
Example:

Profiler profiler = new Profiler();
profiler.startCollecting();

// application code
conn.close();

System.out.println(profiler.getTop(10));

Regards,
Thomas

[wburzyns]

Hi,

The traces are below. Note that I switched to one table (instead of
two previously). The row count is now 5895778.

run:
*** H2 PROFILER OUTPUT BELOW ***
Profiler: top 10 stack trace(s) of 24453 ms [build-153]:
318/1563 (20%):
at java.io.RandomAccessFile.readBytes(Native Method)
at java.io.RandomAccessFile.read(RandomAccessFile.java:322)
at java.io.RandomAccessFile.readFully(RandomAccessFile.java:381)
at org.h2.store.FileStore.readFully(FileStore.java:285)
at org.h2.store.PageStore.readPage(PageStore.java:1270)
at org.h2.store.PageStore.getPage(PageStore.java:706)
at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:222)
at org.h2.index.PageDataNode.getNextPage(PageDataNode.java:226)
at org.h2.index.PageDataLeaf.getNextPage(PageDataLeaf.java:391)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:90)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
312/1563 (19%):
at java.io.RandomAccessFile.readBytes(Native Method)
at java.io.RandomAccessFile.read(RandomAccessFile.java:322)
at java.io.RandomAccessFile.readFully(RandomAccessFile.java:381)
at org.h2.store.FileStore.readFully(FileStore.java:285)
at org.h2.store.PageStore.readPage(PageStore.java:1270)
at org.h2.store.PageStore.getPage(PageStore.java:706)
at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:222)
at org.h2.index.PageDataNode.getNextPage(PageDataNode.java:226)
at org.h2.index.PageDataLeaf.getNextPage(PageDataLeaf.java:391)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:90)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:147)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
72/1563 (4%):
at org.h2.store.PageStore.getPage(PageStore.java:699)
at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:222)
at org.h2.index.PageDataLeaf.getNextPage(PageDataLeaf.java:390)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:90)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:147)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
68/1563 (4%):
at org.h2.value.ValueBoolean.getBoolean(ValueBoolean.java:57)
at org.h2.expression.Expression.getBooleanValue(Expression.java:180)
at org.h2.command.dml.Select.queryFlat(Select.java:515)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
50/1563 (3%):
at org.h2.store.PageStore.getPage(PageStore.java:699)
at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:222)
at org.h2.index.PageDataLeaf.getNextPage(PageDataLeaf.java:390)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:90)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
48/1563 (3%):
at org.h2.value.Value.cache(Value.java:343)
at org.h2.value.ValueLong.get(ValueLong.java:195)
at org.h2.store.Data.readValue(Data.java:639)
at org.h2.index.PageDataLeaf.readRow(PageDataLeaf.java:598)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:329)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:97)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:147)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
41/1563 (2%):
at org.h2.value.Value.cache(Value.java:343)
at org.h2.value.ValueLong.get(ValueLong.java:195)
at org.h2.store.Data.readValue(Data.java:639)
at org.h2.index.PageDataLeaf.readRow(PageDataLeaf.java:598)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:329)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:97)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
40/1563 (2%):
at org.h2.store.Data.readVarLong(Data.java:1097)
at org.h2.store.Data.readValue(Data.java:639)
at org.h2.index.PageDataLeaf.readRow(PageDataLeaf.java:598)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:329)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:97)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:147)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
29/1563 (1%):
at org.h2.store.Data.readVarLong(Data.java:1097)
at org.h2.store.Data.readValue(Data.java:639)
at org.h2.index.PageDataLeaf.readRow(PageDataLeaf.java:598)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:329)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:97)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
26/1563 (1%):
at org.h2.value.Value.getMemory(Value.java:193)
at org.h2.result.Row.getMemory(Row.java:117)
at org.h2.index.PageDataLeaf.memoryChange(PageDataLeaf.java:576)
at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:355)
at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:97)
at org.h2.index.PageDataCursor.next(PageDataCursor.java:49)
at org.h2.index.IndexCursor.next(IndexCursor.java:235)
at org.h2.table.TableFilter.next(TableFilter.java:352)
at org.h2.command.dml.Select.queryFlat(Select.java:513)
at org.h2.command.dml.Select.queryWithoutCache(Select.java:614)
at org.h2.command.dml.Query.query(Query.java:269)
at org.h2.command.dml.Query.query(Query.java:239)
at org.h2.command.dml.Query.query(Query.java:37)
at org.h2.command.CommandContainer.query(CommandContainer.java:78)
at org.h2.command.Command.executeQuery(Command.java:181)
at
org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:
96)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:138)
at org.h2.store.LobStorage.removeAllForTable(LobStorage.java:147)
at org.h2.engine.Database.close(Database.java:1066)
at org.h2.engine.Database.removeSession(Database.java:953)
at org.h2.engine.Session.close(Session.java:572)
at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:337)
at org.aaaStorage.close(MatDbStorage.java:316)
at h2perftest.Main.main(Main.java:29)
packages:
63%: org.h2.store
22%: org.h2.value
4%: org.h2.index
4%: org.h2.expression
.
BUILD SUCCESSFUL (total time: 25 seconds)


Regards,
wburzyns

[Thomas Mueller]

Hi,

Thanks a lot! I understand the problem now.

When closing a connection, the database removes the temporary LOBs for
this connection. But there is no index on this column, which is a
serious performance problem if you have a lot of LOBs.

I will fix this problem for the next release. I think it's very easy
to fix (adding one line to create the index), but of course I will
also add test cases.

Regards,
Thomas

[Thomas Mueller]

Hi,

> Does the fix you propose ("adding one line to create the index") mean
> that I'll have to recreate/reimport all the data when there is a new
> H2 version?

No, the index is automatically added when using the new version at
least once. You could add it yourself actually (after adding a BLOB):

CREATE INDEX IF NOT EXISTS INFORMATION_SCHEMA.INDEX_LOB_TABLE ON
INFORMATION_SCHEMA.LOBS(TABLE);

P.S. please don't send emails to me directly. Please use the Google
Group instead.

Regards,
Thomas

[wburzyns]

Hi,

Sorry for the private posting - it was a mistake. Now I know why my
posts haven't appeared here - erroneously I clicked 'Reply to author'
instead of 'Reply'.

Back to the business: I created an index for the BLOB column of my big
table:

CREATE INDEX IF NOT EXISTS CONTENT_INDEX ON TABLE(CONTENT)

The operation took 27557765 ms (for a DB of size as specified in my
first post) and now the DB closing is virtually instant.
Unfortunately another problem emerged: now insert time is more than
twice as long as it was previously. This is a disaster and cosidering
the two: (1) long closing time (2) long insert time I choose long
closing time.

So regarding the fix you propose (automatic index creation for LOB
columns): will there be an option to have it disabled? I never do any
SELECTs with the BLOB column involved in WHERE clause.
Or perhaps would it be possible to specify that the index shall use
only the first N characters of a BLOB (as done by MySQL:
http://dev.mysql.com/doc/refman/5.5/en/column-indexes.html). On the
other side I doubt if that helps in my case: I store files and all of
them have a common header. So specifying the N first bytes is not
enough, there should be possibility to specify their offset as well...


Regards,
wburzyns

[JavaGuy]

Just an interesting note: using 1.2.127 it's about 5 times slower
closing the db when using BLOBs compared to VARBINARY.

[wburzyns]

> it's about 5 times slower closing the db when using BLOBs compared to VARBINARY

Yeah, Thomas suggested that in another thread. Because now it seems
that the problem with closing a DB with millions of BLOBs might not -
if I'm not mistaken - have a good solution I'm going to re-evaluate my
earlier decision to use BLOB instead of BINARY. I'll let you guys know
my findings.


Bests,
wburzyns

[wburzyns]

On a DB ("jdbc:h2:path;PAGE_SIZE=4096") with single table containing
205k rows:

BLOB: Insert is approx. 5% faster than in case of BINARY.
BLOB: The DB file is almost 39% smaller than in case of BINARY.
BLOB: The DB close time is 150% longer than in case of BINARY.

So generally I'd like to stay with BLOB.


wburzyns

[wburzyns]

Hi Thomas,

With the latest version (1.3.154) the issue doesn't occur anymore - DB
closing is almost instant (less than 1s). There is also no noticeable
performance drop with regard to inserts - I must have screwed up
something with the index I created on my own.



Many thanks,
wburzyns

[Thomas Mueller]

Hi,

By the way, when testing, you need to ensure the content of each BLOB
is different. Otherwise, only one BLOB will actually be stored, and
all others just reference that one. One way to generate random data is
using java.util.Random.

Regards,
Thomas