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.