[Db-derby Wiki] Update of "LogStamentTextMsgs" by StanleyBradbury

[Apache Wiki <wi...@apache.org>]

Dear Wiki user,

You have subscribed to a wiki page or wiki category on "Db-derby Wiki" for change notification.

The following page has been changed by StanleyBradbury:
http://wiki.apache.org/db-derby/LogStamentTextMsgs

New page:
## Added 2006-08-13
== 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:
 * (SESSIONID = ''<connection-id>'') - Identifies a specific connection.  Most tracing is done on a specific {{{SESSIONID}}}.  This field in combination with the ''<dbname>'' identifies a unique connection and transaction sequence.
 * ''<record-timestamp>'' GMT - Shows the time of the activity.  The elapsed time for an activity can be can often be approximated by computing the time between consecutive timestamps for records with the same {{{SESSIONID}}} and  ''<dbname>''.  Note that the time is for Greenwich Mean Time.  To correlate message logfile entries with times reported by an application the proper timezone adjustment will need to be made.
 * ''<activity-label>'' - Identifies the action being performed (e.g. ''Compiling'', ''Executing'', etc.).
 * ''<sql-statement>'' - Identifies a particular SQL statement.  Note that other connections can execute the same SQL.

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.