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:
l:nn- The length of the SQL. Will not appear if there are no parameters (see below).#:nn- The number of rows returned or affected. Will not appear if no rows were found or affected.t:nn- The execution time in milliseconds. Will not appear if the time was less than 1 ms.- 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:
- Self - The percentage of the given command's time from the total time.
- Accu - The percentage of the accumulated time from the total time. The accumulated time is the time of the commands listed so far.
- Time - The total time of the command executions in milliseconds.
- Count - the number of times the command was executed.
- Result - the total number of fetched or affected rows.
- 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.
However, there's a big difference. FTE can help you prevent procrastination by giving you a small "reminder" whenever you start doing unrelated stuff on your machine. Now, you're probably thinking: "I can ignore those remainders, there's nothing new here". Trust me, you won't ignore this one, since it comes in the form of an electric shock. 
Recent Comments