Reading logStatementText messages to find the compile and execution times of a statement

The derby property logStatementText provides information useful in understanding what is occurring at the database level in a Derby system when an application is executed. With a basic understanding of the message log entries created and by searching for identifying text a profile of the usage and responsiveness of specific SQL transactions and transaction sequences can be created. This technique is useful when investigating problems with concurrency and performance. The following describes how to step through message logfile entries generated by logStatementText during the execution of an application that performs a series of uninterrupted database calls. This simple example focuses on identifying the compilation and subsequent execution times for a specific statement. Note how even in this simple, single thread environment the execution time is not constant.

Reading the messages

The exact information in a logStatementText message varies with the architecture of the system and activity being performed but will have this basic format: {{{ <record-timestamp> GMT <thread-info> (XID = <transaction-id-nbr>), (SESSIONID = <connection-id>) <dbname>, <network-connection-info> , <activity-label>: <sql-statement> :<end-statement-marker>

Example 2006-08-11 18:14:54.033 GMT Thread[main,5,main] (XID = 108), (SESSIONID = 0), (DATABASE = jdbcDemoDB), (DRDAID = null), Executing prepared statement: update WISH_LIST set ENTRY_DATE = CURRENT_TIMESTAMP, WISH_ITEM = 'TEST ENTRY' :End prepared statement }}} The message fields used in the trace example below are:

The following abbreviated logfile messages will be referenced in the following trace instructions.

{{{ 2006-08-11 23:11:47.221 GMT <thread-info> (XID = 422141), (SESSIONID = 0), <dbname>, <network-connection-info>, Begin compiling prepared statement: select * from InfoTbl where Info_Id between ? and ? :<end-statement-marker> 2006-08-11 23:11:48.262 GMT <thread-info> (XID = 422141), (SESSIONID = 0), <dbname>, <network-connection-info>, End compiling prepared statement: select * from InfoTbl where Info_Id between ? and ? :<end-statement-marker> 2006-08-11 23:11:48.373 GMT <thread-info> (XID = 422141), (SESSIONID = 0), <dbname>, <network-connection-info>, Executing prepared statement: select * from InfoTbl where Info_Id between ? and ? :<end-statement-marker> 2006-08-11 23:11:48.403 GMT <thread-info> (XID = 422141), (SESSIONID = 0), <dbname>, <network-connection-info>, Committing 2006-08-11 23:11:48.403 GMT <thread-info> (XID = 422143), (SESSIONID = 0), <dbname>, <network-connection-info>, Executing prepared statement: select * from InfoTbl where Info_Id between ? and ? :<end-statement-marker> 2006-08-11 23:11:48.413 GMT <thread-info> (XID = 422143), (SESSIONID = 0), <dbname>, <network-connection-info>, Committing 2006-08-11 23:11:48.413 GMT <thread-info> (XID = 422144), (SESSIONID = 0), <dbname>, <network-connection-info>, Executing prepared statement: select * from InfoTbl where Info_Id between ? and ? :<end-statement-marker> 2006-08-11 23:11:48.413 GMT <thread-info> (XID = 422144), (SESSIONID = 0), <dbname>, <network-connection-info>, Committing }}}

Computing the elapsed times

Search in the log for the SQL string you want to investigate (or a unique subset of the SQL text). The first entry should have the activity-label Begin compiling prepared statement. Note the SESSIONID and timestamp. Find the entry with the activity-label End compiling prepared statement and subtract the begin-timestamp from the end-timestamp to compute the elapsed compile time. The compile time from the example logfile entries is 0.041 seconds (e.g. 23:11:48.262 - 23:11:47.221).

Find the next occurrence of the SQL string that has the activity-label Executing prepared statement and the SESSIONID of the connection. Compute the elapsed execution time by subtracting this timestamp from the timestamp of the next log entry found for the connection which will have the activity-label Committing if autocommit is active. If autocommit is off the activity-label of the next entry will differ and the time computed may contain non-database processing performed by the program (e.g. resultSet processing, etc.). In most cases the non-database processing will be a constant and, hopefully, minimal so elapsed time differences with other executions of the SQL can be assumed to be related to database responsiveness. The executions times computed for the example log are: 1 - 0.070 seconds, 2 - 0.010 seconds, 3 - less than 0.010 seconds.

LogStamentTextMsgs (last edited 2009-09-20 22:12:08 by localhost)