I suspect the "insert into..." behavior is affected by indexes in a way
that looping over "insert" is not. Could this be a buffer issue of some
kind, like "insert into..." treats the entire operation as one, while a
loop over "insert" is treated as a bunch of smaller operations?
If I create the 2nd table without a primary key, populate the table with
"insert into", then add the primary key, the total time is comparable to
the load time of the 1st table, or the load time of doing loop over
"insert" on the 2nd table.
I updated the script like so
(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"))
(exec-raw "create table scores2 as select * from scores limit 0") ;
create table w/o index
; (.startCollecting prof)
(time (exec-raw "insert into scores2 select * from scores"))
; copy data into 2nd table
(time (exec-raw "alter table scores2 alter column id set not null")) ;
make id not null
(time (exec-raw "alter table scores2 add constraint scores2_id primary
key (id)")))) ; add primary key
"Elapsed time: 7769.717 msecs"
"Elapsed time: 7899.676 msecs"
"Elapsed time: 474.536 msecs"
"Elapsed time: 919.515 msecs"
100000
On Monday, September 16, 2013 9:31:33 AM UTC-7, Brian Craft wrote:
>
> 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.
