One more data point: if copy the table by doing a bunch of inserts from the
application code, this performance difference disappears. It's something
peculiar to "insert into .. select"
On Friday, September 13, 2013 5:22:05 PM UTC-7, Brian Craft wrote:
>
> Added the h2 profiler calls. Here's the output.
>
> > rm testdb*; lein exec -p < testscript
> Sep 13, 2013 4:58:19 PM com.mchange.v2.log.MLog <clinit>
> INFO: MLog clients using java 1.4+ standard logging.
> Reflection warning, null:32:5 - reference to field startCollecting can't
> be resolved.
> Reflection warning, null:34:5 - reference to field stopCollecting can't be
> resolved.
> "Elapsed time: 11578.412 msecs"
> "Elapsed time: 362832.799 msecs"
> Reflection warning, null:36:10 - call to getTop can't be resolved.
> Profiler: top 3 stack trace(s) of 362832 ms:
> 67000/100713 (66%):
> at org.h2.store.PageStore.checkpoint(PageStore.java:448)
> at org.h2.store.PageStore.commit(PageStore.java:1438)
> at org.h2.engine.Database.commit(Database.java:1764)
> at org.h2.engine.Session.commit(Session.java:452)
> at org.h2.schema.Sequence.flush(Sequence.java:134)
> at org.h2.table.Column.updateSequenceIfRequired(Column.java:337)
> at org.h2.table.Column.validateConvertUpdateSequence(Column.java:319)
> at org.h2.table.Table.validateConvertUpdateSequence(Table.java:692)
> at org.h2.command.dml.Insert.addRow(Insert.java:159)
> at org.h2.command.dml.Insert.insertRows(Insert.java:137)
> at org.h2.command.dml.Insert.update(Insert.java:84)
> at org.h2.command.CommandContainer.update(CommandContainer.java:75)
> at org.h2.command.Command.executeUpdate(Command.java:230)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:156)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeBatch(JdbcPreparedStatement.java:1106)
> at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
> at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:298)
> at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:414)
> at clojure.java.jdbc$do_prepared$fn__123.invoke(jdbc.clj:497)
> at clojure.java.jdbc$transaction_STAR_.invoke(jdbc.clj:368)
> at clojure.java.jdbc$do_prepared.doInvoke(jdbc.clj:497)
> at clojure.lang.RestFn.invoke(RestFn.java:423)
> at korma.db$exec_sql.invoke(db.clj:207)
> at korma.db$do_query.invoke(db.clj:225)
> at korma.core$exec_raw.doInvoke(core.clj:489)
> at clojure.lang.RestFn.invoke(RestFn.java:410)
> at user$eval14$myfuncb__15.invoke(Unknown Source)
> at clojure.java.jdbc$with_connection_STAR_.invoke(jdbc.clj:309)
> at user$eval14.invoke(Unknown Source)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> at clojure.lang.Compiler.load(Compiler.java:7064)
> at clojure.lang.Compiler.load(Compiler.java:7029)
> at clojure.core$load_reader.invoke(core.clj:3696)
> at user$eval5.invoke(NO_SOURCE_FILE:1)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> at clojure.lang.Compiler.eval(Compiler.java:6609)
> at clojure.lang.Compiler.eval(Compiler.java:6582)
> at clojure.core$eval.invoke(core.clj:2852)
> at clojure.main$eval_opt.invoke(main.clj:308)
> at clojure.main$initialize.invoke(main.clj:327)
> at clojure.main$null_opt.invoke(main.clj:362)
> at clojure.main$main.doInvoke(main.clj:440)
> at clojure.lang.RestFn.invoke(RestFn.java:421)
> at clojure.lang.Var.invoke(Var.java:419)
> at clojure.lang.AFn.applyToHelper(AFn.java:163)
> 12731/100713 (12%):
> at org.h2.store.PageStore.checkpoint(PageStore.java:447)
> at org.h2.store.PageStore.commit(PageStore.java:1438)
> at org.h2.engine.Database.commit(Database.java:1764)
> at org.h2.engine.Session.commit(Session.java:452)
> at org.h2.schema.Sequence.flush(Sequence.java:134)
> at org.h2.table.Column.updateSequenceIfRequired(Column.java:337)
> at org.h2.table.Column.validateConvertUpdateSequence(Column.java:319)
> at org.h2.table.Table.validateConvertUpdateSequence(Table.java:692)
> at org.h2.command.dml.Insert.addRow(Insert.java:159)
> at org.h2.command.dml.Insert.insertRows(Insert.java:137)
> at org.h2.command.dml.Insert.update(Insert.java:84)
> at org.h2.command.CommandContainer.update(CommandContainer.java:75)
> at org.h2.command.Command.executeUpdate(Command.java:230)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:156)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeBatch(JdbcPreparedStatement.java:1106)
> at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
> at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:298)
> at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:414)
> at clojure.java.jdbc$do_prepared$fn__123.invoke(jdbc.clj:497)
> at clojure.java.jdbc$transaction_STAR_.invoke(jdbc.clj:368)
> at clojure.java.jdbc$do_prepared.doInvoke(jdbc.clj:497)
> at clojure.lang.RestFn.invoke(RestFn.java:423)
> at korma.db$exec_sql.invoke(db.clj:207)
> at korma.db$do_query.invoke(db.clj:225)
> at korma.core$exec_raw.doInvoke(core.clj:489)
> at clojure.lang.RestFn.invoke(RestFn.java:410)
> at user$eval14$myfuncb__15.invoke(Unknown Source)
> at clojure.java.jdbc$with_connection_STAR_.invoke(jdbc.clj:309)
> at user$eval14.invoke(Unknown Source)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> at clojure.lang.Compiler.load(Compiler.java:7064)
> at clojure.lang.Compiler.load(Compiler.java:7029)
> at clojure.core$load_reader.invoke(core.clj:3696)
> at user$eval5.invoke(NO_SOURCE_FILE:1)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> at clojure.lang.Compiler.eval(Compiler.java:6609)
> at clojure.lang.Compiler.eval(Compiler.java:6582)
> at clojure.core$eval.invoke(core.clj:2852)
> at clojure.main$eval_opt.invoke(main.clj:308)
> at clojure.main$initialize.invoke(main.clj:327)
> at clojure.main$null_opt.invoke(main.clj:362)
> at clojure.main$main.doInvoke(main.clj:440)
> at clojure.lang.RestFn.invoke(RestFn.java:421)
> at clojure.lang.Var.invoke(Var.java:419)
> at clojure.lang.AFn.applyToHelper(AFn.java:163)
> 3101/100713 (3%):
> at java.io.RandomAccessFile.writeBytes(Native Method)
> at java.io.RandomAccessFile.write(RandomAccessFile.java:466)
> at org.h2.store.fs.FileDisk.write(FilePathDisk.java:433)
> at org.h2.store.fs.FileUtils.writeFully(FileUtils.java:356)
> at org.h2.store.FileStore.write(FileStore.java:324)
> at org.h2.store.PageStore.writePage(PageStore.java:1327)
> at org.h2.store.PageStreamData.write(PageStreamData.java:105)
> at org.h2.store.PageOutputStream.storePage(PageOutputStream.java:146)
> at org.h2.store.PageOutputStream.flush(PageOutputStream.java:154)
> at org.h2.store.PageLog.checkpoint(PageLog.java:676)
> at org.h2.store.PageStore.checkpoint(PageStore.java:440)
> at org.h2.store.PageStore.commit(PageStore.java:1438)
> at org.h2.engine.Database.commit(Database.java:1764)
> at org.h2.engine.Session.commit(Session.java:452)
> at org.h2.schema.Sequence.flush(Sequence.java:134)
> at org.h2.table.Column.updateSequenceIfRequired(Column.java:337)
> at org.h2.table.Column.validateConvertUpdateSequence(Column.java:319)
> at org.h2.table.Table.validateConvertUpdateSequence(Table.java:692)
> at org.h2.command.dml.Insert.addRow(Insert.java:159)
> at org.h2.command.dml.Insert.insertRows(Insert.java:137)
> at org.h2.command.dml.Insert.update(Insert.java:84)
> at org.h2.command.CommandContainer.update(CommandContainer.java:75)
> at org.h2.command.Command.executeUpdate(Command.java:230)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:156)
> at
> org.h2.jdbc.JdbcPreparedStatement.executeBatch(JdbcPreparedStatement.java:1106)
> at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
> at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:298)
> at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:414)
> at clojure.java.jdbc$do_prepared$fn__123.invoke(jdbc.clj:497)
> at clojure.java.jdbc$transaction_STAR_.invoke(jdbc.clj:368)
> at clojure.java.jdbc$do_prepared.doInvoke(jdbc.clj:497)
> at clojure.lang.RestFn.invoke(RestFn.java:423)
> at korma.db$exec_sql.invoke(db.clj:207)
> at korma.db$do_query.invoke(db.clj:225)
> at korma.core$exec_raw.doInvoke(core.clj:489)
> at clojure.lang.RestFn.invoke(RestFn.java:410)
> at user$eval14$myfuncb__15.invoke(Unknown Source)
> at clojure.java.jdbc$with_connection_STAR_.invoke(jdbc.clj:309)
> at user$eval14.invoke(Unknown Source)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> at clojure.lang.Compiler.load(Compiler.java:7064)
> at clojure.lang.Compiler.load(Compiler.java:7029)
> at clojure.core$load_reader.invoke(core.clj:3696)
> at user$eval5.invoke(NO_SOURCE_FILE:1)
> at clojure.lang.Compiler.eval(Compiler.java:6619)
> summary:
> 79%: org.h2.store
> 13%: org.h2.store.fs
> 4%: org.h2.util
> .
>
>
> On Friday, September 13, 2013 1:22:13 PM UTC-7, Brian Craft wrote:
>>
>> Here's a trivial clojure script to invoke this behavior. It uses sql
>> korma to access the db, but the code should be obvious even if you don't
>> know this library.
>>
>> The game here is to create a table, put some rows of varbinary data in
>> it, and then copy to another table.
>>
>> (require 'korma.db)
>> (use 'korma.core)
>>
>> (def file "testdb;LOG=1;CACHE_SIZE=65536")
>> (def score-size 400)
>> (def rows 1000)
>>
>> (defn- scores-table-name [name]
>> (format "CREATE TABLE IF NOT EXISTS `%s` (
>> `id` INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
>> `expScores` VARBINARY(%d) NOT NULL)" name score-size))
>>
>>
>> (def mydb
>> (korma.db/create-db
>> {:classname "org.h2.Driver"
>> :subprotocol "h2"
>> :subname file}))
>>
>> (def one-score (byte-array (map byte (repeat 400 1)))) ; 400 bytes of 0x01
>>
>> (korma.db/with-db
>> mydb
>> (do
>> (exec-raw (scores-table-name "scores"))
>> (time (doseq [_ (range rows)]
>> (exec-raw ["insert into scores (expScores) values (?)"
>> [one-score]])))
>> (exec-raw (scores-table-name "scores2"))
>> (time (exec-raw "insert into scores2 select * from scores"))))
>>
>>
>> Some results, below. The value of "rows" (the row count) is returned on
>> the last line of each case.
>>
>> > rm testdb*; lein exec -p < testscript
>> Sep 13, 2013 1:06:38 PM com.mchange.v2.log.MLog <clinit>
>> INFO: MLog clients using java 1.4+ standard logging.
>> "Elapsed time: 11522.797 msecs"
>> "Elapsed time: 347517.094 msecs"
>> (100000)
>>
>> > rm testdb*; lein exec -p < testscript
>> Sep 13, 2013 1:13:13 PM com.mchange.v2.log.MLog <clinit>
>> INFO: MLog clients using java 1.4+ standard logging.
>> "Elapsed time: 2008.599 msecs"
>> "Elapsed time: 879.88 msecs"
>> (10000)
>>
>> > rm testdb*; lein exec -p < testscript
>> Sep 13, 2013 1:13:35 PM com.mchange.v2.log.MLog <clinit>
>> INFO: MLog clients using java 1.4+ standard logging.
>> "Elapsed time: 329.684 msecs"
>> "Elapsed time: 195.243 msecs"
>> (1000)
>>
>>
>> So, between 10k rows and 100k rows the performance of the "insert into ..
>> select" goes from being around half the 1st table load time, to being
>> around 30x the 1st table load time.
>>
>>
>>
>> On Friday, September 13, 2013 11:43:11 AM UTC-7, Brian Craft wrote:
>>>
>>> I could put together a test case in clojure. Do you want that?
>>>
>>> I'm not sure what it will tell you, since it's not the loader code that
>>> is slow.
>>>
>>> On Friday, September 13, 2013 10:08:39 AM UTC-7, Noel Grandin wrote:
>>>>
>>>> If you can post the test-case code, I can look at it on monday.
>>>>
>>>
--
You received this message because you are subscribed to the Google Groups "H2
Database" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To post to this group, send email to [email protected].
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.
