Appendix L: E-Mail Performance Monitoring

Introduction

From CopiaFacts engine release 7.218 and CF8EMAIL.DLL release 7.207 onwards, optional performance monitoring features are available to analyze e-mail throughput. The monitoring is enabled by checking the 'E-Mail Timers' option in the COPIAFACTS program.

Operation

The results of the monitoring process are made available in (currently six) system variables EM_TIMER01 through EM_TIMER06. The variables are written into the processed FS file in the normal way, and are also available during post-processing for custom processing.

The value of each system variable is a time interval in microseconds for a particular stage of e-mail processing.  Because operations on an e-mail transaction continue after the writing of an FS file and during post-processing, the first value in the set of interval times in recorded in each FS file will actually be that of the final stage of the immediately preceding operation handled by the same thread.  This is unlikely to cause a problem because these intervals are unlikely to differ greatly from one e-mail to the next.

The timers feature is designed for investigation and occasional monitoring of specific performance issues in high-volume e-mail applications.  We strongly discourage the use of the timer values on a permanent basis or for any accounting purpose.  The precise interval points and the number of time intervals recorded will change over time in future CopiaFacts releases.

If an e-mail transmission fails, some of the interval recording points may be bypassed and so some of the variables may not be set. The variable expansion in this case will be zero.

The current time intervals are measured as follows:

EM_TIMER01Post-Process Time.  This timer measures the interval from the completion of the previous e-mail transmission handled by the same thread, up to the completion of all processing of the transaction (FS file). The value will be zero for the first transaction on a thread after CopiaFacts startup.
EM_TIMER02Get-Next Time.  This timer measures the time taken to find, read and parse the current FS file, from the end of the processing of the previous file by the thread, up to the point where e-mail processing starts for the current transaction.  The value is really only of interest in an environment where MSMQ is used to deliver e-mail FS images to CopiaFacts, and not when actual FS files on disk are scanned for.  If your system has e-mail threads which are only used occasionally, you may find an extremely large value in this variable, representing the number of microseconds since the thread was last used for e-mail since CopiaFacts startup.
EM_TIMER03MX Lookup Time.  This timer measures the time taken to find the MX records for the target domain.
EM_TIMER04Headers Time.  This timer measures the time taken to process the email headers (including variable expansion and quoted-printable encoding if applicable).
EM_TIMER05Body Text Time.  This timer measures the time taken to process the body and altbody text (including variable expansion and quoted-printable encoding if applicable).
EM_TIMER06SMTP Transmission Time. This timer measures the time taken to log in and transmit the data (headers, text and attachments) to the remote MTA.  It is the aggregate of all attempts if it is necessary to try more than one MX record. At the end of this interval the finish time is saved as the base for TIMER01 in the next transaction to be handled by the thread.

Cautions

With all the above timers, the intervals represent actual clock time, and will therefore increase for an individual thread as more threads consume CPU cycles and IP bandwidth.

The resolution of the timers depends on the actual CPU in use. With most modern CPUs a resolution of the order of a microsecond is typical.  The timer we use is documented by Microsoft as sometimes being slightly inaccurate in a system with multiple processors or processor cores.

It is recommended that programs used to process the timer values are capable of extended-precision (or 64-bit-integer) arithmetic because the numbers (in μs) can be large.