Check Reads from Transaction Log Files

In some situations a "log reader," such as a master replication agent 'transmitter' thread or a ttXlaNextUpdate call in an XLA application, may not be able to keep up with the update rate of the applications writing to the database. Normally, replication and XLA readers get update records from the log buffer in memory. When the readers fall behind the application update rate, transaction log files can accumulate on the file system until the backlog can be cleared. This forces the readers to read transactions from the transaction log files on the file system, which is much slower. Should you detect reads from the transaction log files, you may want to respond by decreasing the rate of application updates to that sustainable by the log readers.

Applications can monitor whether log readers are obtaining update records from transaction log files on the file system rather than from the log buffer in memory by tracking the SYS.MONITOR table entry LOG_FS_READS. For example, you can check the value of LOG_FS_READS for the database, MASTERDSN, with the following ttIsql command.

% ttIsql -v1 -e "select log_fs_reads from monitor; quit;" -connStr dsn=MASTERDSN

If the LOG_FS_READS counter is increasing, the log readers are falling behind or clearing out a backlog in the transaction log files.

For more complete monitoring of replication progress, create a simple shell script like the following:

!/bin/sh
trap exit 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
DSN=$1

while [ 1 ] ; do
   date
   ttRepAdmin -receiver -list -connStr dsn=$DSN
   echo -n "Log reads from disk: "
   ttIsql -v1 -e "select log_fs_reads from monitor; quit;" -connStr dsn=$DSN
   echo
   ttRepAdmin -bookmark -connStr dsn=$DSN
sleep 15
done

For example, you name the above script monitorLog and your replication scheme replicates from the MASTERDSN database to the SUBSCRIBER1DSN database. You can then check the status of the transaction log by entering:

% monitorLog masterdsn

This generates output similar to the following:

Mon Aug  2 10:44:40  2004
Peer name         Host name                 Port    State  Proto
----------------  ------------------------ ------  ------- -----
SUBSCRIBER1DSN    MYHOST                    Auto    Start   12

Last Msg Sent Last Msg Recv Latency TPS     RecordsPS Logs
------------- ------------- ------- ------- --------- ----
00:00:05      -               -1.00      -1        -1    1

Log reads from disk: < 0 >

Replication hold LSN ...... 10/2656136
Last written LSN .......... 10/4015824
Last LSN forced to disk ... 10/3970152

The output from the script displays an updated status every 15 seconds until you enter Ctrl-C to exit.

The specific meaning of each value is described in Display Subscriber Status with the ttRepAdmin Utility in the Oracle TimesTen In-Memory Database Replication Guide. The main interest here is the 'Last Msg Sent' and 'Logs' values. The 'Last Msg Sent' value indicates the elapsed time since the last message was sent by the master to the subscriber and 'Logs' indicates how many transaction log files behind the replication log reader is from the current log insertion point used by the writers (Last written LSN).

Normally the Logs value should be 1. A steadily increasing Logs value indicates latency is increasing and eventually log reads are satisfied from the file system.

Note:

If the LogBufMB is larger than the LogFileSize, an increase in the 'Logs' value does not necessarily mean the log readers are reading from the transaction log files. This is because the log manager does not allow more than one log file's worth of data to be outstanding before writing it to the file system. After the log manager writes the data, the data remains in the log buffer to be read directly by the log readers. So, when the LogBufMB is larger than the LogFileSize, the 'Logs" value alone may not be the best measure of whether log readers are reading from memory or from the file system.

The output from the following command displays the number of the transaction log files and the location of the bookmarks set by the log manager.

ttRepAdmin -bookmark -connStr dsn=$DSN

For more information, see Monitor Replication with the ttRepAdmin Utility in the Oracle TimesTen In-Memory Database Replication Guide. The difference between the Replication hold LSN and the last written LSN indicates the number of records in the transaction log that have not yet been transmitted to the subscribers. A steady increase in the difference between these values is another indication that replication latency is increasing and log file reads are likely to occur.

In this example, assume the LogBufMB is 16MB and the LogFileSize is 8MB. The following output indicates the log reader is approximately 1.8 MB behind the capacity of the log buffer and must read from the transaction log files, 14 and 15.

Peer name         Host name                Port    State   Proto
----------------  ------------------------ ------  ------- -----
SUBSCRIBER1DSN    MYHOST                   Auto    Start   12

Last Msg Sent Last Msg Recv Latency TPS     RecordsPS Logs
------------- ------------- ------- ------- --------- ----
00:00:03      -               -1.00      -1        -1    4

Log reads from disk: <20>

Replication hold LSN ...... 14/7007464
Last written LSN .......... 17/465336
Last LSN forced to disk ... 17/456152