For details on how to set the APPX_DBGL_CODE to log specific RDBMS activity, see http://board.appx.com/faq/cache/634.html

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.

  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.