How to read the APPX_SQL_CMD Log

How to set the APPX_SQL_CMD to obtain a log of RDBMS activity, see How to set the APPX_SQL_CMD to obtain a log of RDBMS activity.

For details on how to set the APPX_DBGL_CODE to log specific RDBMS activity, see How to set the APPX_DBG_CODE to log specific RDBMS activity

Reading the SQL Log file

Please note the Tips and Techniques section below for information on what to look for in this log.

After your benchmark run, the /tmp/rdbms.log file will contain a set of entries similar to:

00 - 0000072.0797031 0000000.0057123 05000
01 - 0000076.0737460 0000000.0043817 10001
02 - 0000000.0000000 0000000.0000000 00000
03 - 0000000.0000000 0000000.0000000 00000
04 - 0000000.0022587 0000000.0022573 00002
05 - 0000000.0000000 0000000.0000000 00000
06 - 0000026.0281965 0000000.0031189 05001
07 - 0000002.0012514 0000000.0012999 15003
08 - 0000000.0000000 0000000.0000000 00000
09 - 0000000.0000000 0000000.0000000 00000
10 - 0000000.0017440 0000000.0017440 00001
11 - 0000024.0951585 0000000.0022819 05000

You will have one entry for each table accessed by Appx (there may be multiple entries for some tables - we log statistics each time we close a table).

Each entry contains an array of 12 rows and 4 columns. The columns (from left to right) represent:

operation type
cumulative time spent performing that operation for that table
longest operation of that type for that table
number of operations of that type for that table

The rows are:

00 - Read operations
01 - Readnext operations
02 - Write operations
03 - Rewrite operations
04 - Open operations
05 - Reread operations
06 - Search operations
07 - Release operations
08 - Search by primary key operations
09 - Search by alternate key(s) operations
10 - Position to start of table operations
11 - Search by row identifier operations

Dissecting the first row of the above example:

00 - 0000072.0797031 0000000.0057123 05000

The operation type is '00' or "Read". We spent a little over 72 seconds performing Read operations against this table. The longest read took .0057123 seconds, and we performed exactly 5000 reads.

Some of operation types are composites: for example, a READ statement is accomplished by performing a Search followed by a Readnext. So you can see in the above example that we performed 5000 reads, comprised of 5000 Searches and 5000 Readnexts.

00 - Read operations

As mentioned above, a Read is performed whenever Appx needs to retrieve
a record by a specific key value.  A Read is accomplished by performing a
Search followed by a Readnext, so you should have at least as many Searches
and Readnexts as you have Reads.

01 - Readnext operations

A Readnext is performed whenever Appx has established a Search position
within a file and then needs to retrieve the record following that position.
A Readnext will be performed for READNEXT, BEG/END READ, and READ statements
as well as for most PCF operations.

02 - Write operations

A Write operation is equivalent to a WRITE statement - it causes a row to be
INSERTed into a table.

03 - Rewrite operations

A Rewrite operation is equivalent to a REWRITE statement - is causes an SQL
UPDATE statement to be executed.

04 - Open operations

This entry reflects the amount of time required to open a table.  It includes
querying the RDBMS data dictionary and performing all internal bookkeeping.
The time required for this operation is usually negligible.

05 - Reread operations

Since Sybase does not perform row-level locking, Appx must simulate locking
outside of the Sybase server. The algorithm used to simulate locking requires
reading every locked record twice: once to retrieve the key values and once
to read the rest of the record.  A Reread operation reflects the second read.
There should be one Reread operation for each record held.

06 - Search operations

A Search operation is performed whenever Appx needs to position to a specific
key value.  Searches are usually (but not always) performed by a Readnext
operation and are usually part of a BEG AT or READ operation.  Search
operations are further divided into "Search by primary key", "Search by
alternate key(s)", "Position to start of table", and "Search by row dentifier
operations".  In the above example, you can see that we performed 5001
searches: 1 position to start-of-table and 5000 read by row-id's.

07 - Release operations

A Release operation is performed whenever Appx releases a hold on a locked
record.  Appx will try to release holds on records which were not locked -
the overhead is negligible and does not cause any i/o.

08 - Search by primary key operations

This a subdivision of the Search operation.  It reflects the number of
Search operations which specify a primary key value.  In Sybase - primary
keys are implemented as a clustered index.

09 - Search by alternate key(s) operations

This a subdivision of the Search operation.  It reflects the number of
Search operations which specify an alternate key value.

10 - Position to start of table operations

This a subdivision of the Search operation.  It reflects the number of
Search operations which position to the first row in an index (as opposed
to a specific key value).

11 - Search by row identifier operations

This is a subdivision of the Search operation.  Whenever Appx reads a
row from a table, it remembers the row-identifier (in the case of Sybase,
the row-id is the primary key).  If Appx needs to reposition to that row,
it will use the row-id.  An Appx query process works by recording the
row-id's of all records which meet the query constraints and then re-reading
the results using the row-id's.   The above example was produced by selecting
5000 out of 5000 records in a query process.

Tips and Techniques...

When you are examining a statistics log, you should pay particular attention to two results:

1)  The amount of time spent on 00 (Read), 01 (Readnext), 02 (Write),
    03 (Rewrite), 05 (Reread), and 06 (Search) operations.


2)  The number of operations performed against each file compared to
    the number of operations performed against the PCF.

The first statistic will help identify which files are consuming the most amount of time. The second will help identify which files may be processed too frequently.

The "longest operation" column should be roughly equal to cumulative/count - if it's off by more than a factor of 10, it may be worth exploring - of the 'count' operations, (at least) one of them took much longer than the rest.