H2 Trace file information not clear

[Vladimir Albis]

Hi and thanks for all your help. I am using H2 database for an
application that uses Hibernate 3 for complete access to H2. And i
have use trace tool to see the performance.

In SQL Statement Statistics, I do not understand if the Time column is
for the total Count column, or for each execution. I mean if it is
like TimeTotal(new column) = Time * Count. Or for example:

-- self accu time count result sql
-- 32% 32% 266 2 556 select

if 2 executions took 266 millisencods.

Another thing, what is the impact of the command: CALL AUTOCOMMIT()?,
because is executed so many times. Also in my trace files i found this
query: SELECT VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE NAME=?,
like more than 900 times. This sql command it is not generated by the
application.

And last, i have a query that returns in the Result column = 1112;
Count column = 1; Time column = 0. I trust this is correct, because is
H2, isn't? My point here is that Result column is greater than a 1000
and takes 0 Time.

Of course all of this is to get a better performance.

Thank you so much.

[Thomas Mueller]

Hi,

> In SQL Statement Statistics, I do not understand if the Time column is
> for the total Count column, or for each execution. I mean if it is
> like TimeTotal(new column) = Time * Count. Or for example:
>
> -- self accu time count result sql
> -- 32% 32% 266 2 556 select
>
> if 2 executions took 266 millisencods.

Is is the accumulated time, that means it took 133 ms on average. I
will change the output from

-----------------------------------------
-- SQL Statement Statistics
-- time: total time in milliseconds
..

to
-- time: total time in milliseconds (accumulated)

> Another thing, what is the impact of the command: CALL AUTOCOMMIT()?,
> because is executed so many times.

The impact shouldn't be that big. It is called when calling
Connection.getAutoCommit(). I know Hibernate calls this method a lot.
If it is a problem I will try to optimize the method. How much time
(percentage and total milliseconds) did it take in your case?

> Also in my trace files i found this
> query: SELECT VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE NAME=?,
> like more than 900 times. This sql command it is not generated by the
> application.

This is probably also a Connection call, maybe
Connection.getQueryTimeout. How much did it take for you?

> result = 1112, count = 1; time = 0.

> I trust this is correct, because is H2, isn't?

Sure! :-)

> My point here is that Result column is greater than a 1000
> and takes 0 Time.

The statement was called once, it was very fast (0 milliseconds), and
produced an update count or rowcount of 1112 rows. That is possible.
Windows has a time resolution of about 10 milliseconds, so the query
probably took a few milliseconds. But the resolution is not a problem
if a query is executed many times (statistically the error disappears
the more often the query is executed).

I will expand the "Performance" section in the docs in the next
release as follows:

Database Profiling

The ConvertTraceFile tool generates SQL statement statistics at the
end of the SQL script file. The format used is similar to the
profiling data generated when using java -Xrunhprof. As an example,
execute the the following script using the H2 Console:

SET TRACE_LEVEL_FILE 3;
DROP TABLE IF EXISTS TEST;
CREATE TABLE TEST(ID INT PRIMARY KEY, NAME VARCHAR(255));
@LOOP 1000 INSERT INTO TEST VALUES(?, ?);
SET TRACE_LEVEL_FILE 0;

Now convert the .trace.db file using the ConvertTraceFile tool:

java -cp h2.jar org.h2.tools.ConvertTraceFile
-traceFile "~/test.trace.db" -script "~/test.sql"

The generated file test.sql will contain the SQL statements as well as
the following profiling data (results vary):

-----------------------------------------
-- SQL Statement Statistics
-- time: total time in milliseconds (accumulated)
-- count: how many times the statement ran
-- result: total update count or row count
-----------------------------------------

-- self accu time count result sql

-- 62% 62% 158 1000 1000 INSERT INTO TEST VALUES(?, ?);
-- 37% 100% 93 1 0 CREATE TABLE TEST(ID INT PRIMARY
KEY, NAME VARCHAR(255));
-- 0% 100% 0 1 0 DROP TABLE IF EXISTS TEST;
-- 0% 100% 0 1 0 SET TRACE_LEVEL_FILE 3;

Regards,
Thomas

[Vladimir Albis]

Hello, again thanks for your help.

-- self accu time count result sql

-- 4% 75% 45 983 983 SELECT VALUE FROM
INFORMATION_SCHEMA.SETTINGS WHERE NAME=?;
-- 2% 83% 20 2725 2725 CALL AUTOCOMMIT();

As time column is accumulated, i guess the impact is nothing.

And just for comment, after seeing this results, i used a profiling
tool to see what code was takeing more time; the results were
that the aggregate commands (SELECT sum(esa.taaValue) FROM EntSaataa
esa) were more time consuming, follow them the
query commands.

Bye,
Vladimir


On Aug 11, 11:53 pm, "Thomas Mueller" <thomas.tom.muel...@gmail.com>
wrote: