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.
