H2 Database - Performance Tracing

I first wrote about the H2 Database last August. I've been using it since and so far I'm very happy with it. The article I wrote is still getting hits from people searching for information on H2 (here's a fun fact, if you search Google for H2, you'll get the H2 Database before the H2 Hummer) . I'm now working on improving the performance of my application. Like everything else in H2, it is very simple to trace the database performance. This article demonstrates several techniques.

Note: the tools shown here are relevant to H2 starting from version 1.0.70. Since H2 is still work in progress, this may change in the future. I'll do my best to keep this article up to date. I also included some useful links to the original H2 Tutorial.

Generating Trace Files

H2 can output trace files which include the performance information. These trace files contain all the commands executed and their execution details. In the examples hereunder, I will use a database called mydatabase.

First, you need to specify the trace level.  You do this by setting a property called TRACE_LEVEL_FILE. The best way is to simply specify this upon connection to the database. This is done by adding ";TRACE_LEVEL_FILE=n", where n is the trace level, at the end of your database connection string.  The trace levels are: 0=off, 1=error, 2=info, 3=debug. Use trace level 2 or 3 in order to get the performance information. For example:

jdbc:h2:file:~/mydatabase;TRACE_LEVEL_FILE=3

From that point, H2 will start writing trace logs to the directory where the database file is located. The trace file is called mydatabase.trace.db. Once the file reaches the maximum size, it is rotated to mydatabase.trace.db.old (the old one is erased). You can set the size of the log file by setting TRACE_MAX_FILE_SIZE. My connection URL, looks like this:

jdbc:h2:file:~/mydatabase;TRACE_LEVEL_FILE=3;TRACE_MAX_FILE_SIZE=20

H2 is very tolerant regarding trace files. You can rename the file and it will create a new one instead. You can set the trace level at any given time, not only upon connection. You can use the H2 console for that, just connect to your database instance and execute the command:

SET TRACE_LEVEL_FILE=3

Using the Trace Files

SQL commands in the trace files will have the following format:

04-30 11:47:14 jdbc[10]:
/*SQL l:61 #:14 t:1*/SELECT * FROM EMPLOYEES WHERE EMP_ID = ? {1: 243};

The first line shows the date and time. The second line shows the following information:

1. l:nn - The length of the SQL. Will not appear if there are no parameters (see below).
2. #:nn - The number of rows returned or affected. Will not appear if no rows were found or affected.
3. t:nn - The execution time in milliseconds. Will not appear if the time was less than 1 ms.
4. The SQL command itself with all the parameters, in case you're using a prepared statement. You can simply copy the SQL with the parameters and execute it through the H2 Console, which is very handy for debugging.

The trace file is your first stop when checking your performance. You can check every single command and see how it performs.

SQL Command Statistics

H2 includes several tool, among them a utility that generates statistics from a trace file. The tool is called ConvertTraceFile. The tool takes a trace file as input and has two outputs: a Java class (not relevant) and an SQL script which contains all the SQL commands and the execution statistics.

The ConvertTraceFile is invoked in the following manner:

java -cp h2.jar org.h2.tools.ConvertTraceFile -traceFile mydatabase.trace.db

You should specify full paths for h2.jar and your trace file if necessary. Alternatively, make sure h2.jar is in your CLASSPATH. The SQL script will be in a file called mydatabase.sql. You may also specify a different file name (use -? to see all the available options). 

The SQL script file holds all the SQL commands which were executed when the trace file was active. At the end of the file, you will find the command statistics section which has the following form:

--	self	accu	time	count	result	sql
--	89%	89%	3309	12	234	SELECT * FROM EMPLOYEES WHERE EMP_ID = ?;
--	5%	94%	192	1015	1015	UPDATE EMPLOYEES SET NAME=?, DEPT=?, MANAGER=? WHERE EMP_ID=?;
--	2%	97%	87	421	421	UPDATE DEPARTMENTS SET NAME=? WHERE ID=?;
--	0%	97%	26	8123	8123	CALL AUTOCOMMIT();
--	0%	98%	16	18	736	SELECT * FROM DEPARTMENTS WHERE ID = ?;
--	0%	98%	14	424	740	SELECT COUNT(*) FROM DEPARTMENTS;

The columns are:

1. Self - The percentage of the given command's time from the total time.
2. Accu - The percentage of the accumulated time from the total time. The accumulated time is the time of the commands listed so far.
3. Time - The total time of the command executions in milliseconds.
4. Count - the number of times the command was executed.
5. Result - the total number of fetched or affected rows.
6. SQL - the command itself

Needless to say, the statistics you get can easily be imported to OpenOffice Calc or Micsoroft Excel for further manipulation (you can use a fixed column import).

Conclusion

I like simplicity and this is one of the main reasons I enjoy using H2. The above tools enable you to get statistics and detailed information on SQL queries and commands executed in H2.

Good luck with your performance tuning.