Audits for performance profiling

The following hotspots are identified for auditing:

• An operation waits in the worker thread queue for a long time before the worker thread actually starts the operation.
• The time that is spent for cache contention inside the back-end requires tracking.
• The time that is spent in handling client input and output, that is, the time that is spent in receiving the request and returning the result. This value can also be used for detecting bottlenecks because of slow clients or network issues.

Using the audited performance hotspot data, directory administrators can use the system audit facilities to log the LDAP audit record with the system-defined record format.

When you audit the performance profiling, you must consider the following points:

• The configuration options can be enabled to auditing for a combination of different types of operations. For example: auditing for add and modify operations only, along with the auditing for performance.
• At the end of operation execution, the audit information is stored in the server audit logs only. In a scenario where the server is having performance bottlenecks and is in a hung state, the cn=workers, cn=monitor search can be issued. This search gives information about where each worker is stuck. This information is obtained by accumulating information that is collected about the worker until that point in the audit records.

For each operation, performance data field in the audit records is controlled by using the configuration option ibm- auditPerformance. Currently, the following performance data fields are defined for each operation:

operationResponseTime

Represents the time difference in milliseconds between the time the operation was received and the time its response was sent. The operation received time and the response sent time of an operation are published in audit v3 header.

timeOnWorkQ

Represents time in milliseconds spent in the worker queue before execution is initiated on the operation. The value of this field is the difference between the time execution was initiated and the time the operation was received.

rdbmLockWaitTime

Represents time in milliseconds spent in acquiring locks over RDBM caches during operation execution. The value in this field helps administrators to determine the time that is spent for cache contention against real work.

The lock wait time over the following resources are also considered.

• Resource cache
• DN cache
• Entry cache
• Filter cache
• Attribute cache
  Note: From IBM® Security Verify Directory, version 6.3 release, attribute cache is deprecated. Henceforth, users must avoid the use of attribute cache.
• Deadlock detector
• RDBM locks

This field is implemented by introducing of a field in the operation structure. This field is updated when the acquiring of lock is attempted during operation execution. In addition, wrapper functions are introduced for functions that attempt to acquire locks over RDBM caches. These wrapper functions take another operation pointer as parameter and update the lock wait time field of the operation if ibm-auditPerformance is enabled.

clientIOTime

Represents time in milliseconds that was spent in receiving the complete operation request and returning the complete operation response. This field is implemented in the operation structure. It is updated on receiving the complete BER for operation request and on successfully returning the response BER message for the operation.

An example of the audit version 3 format for search operation with ibm-auditPerformance enabled is shown here:

AuditV3--2006-09-09-10:49:01.863-06:00DST--V3 Search--
bindDN: cn=root--client: 127.0.0.1:40722--connectionID: 2--
received: 2006-09-09-10:49:01.803-06:00DST—Success
controlType: 1.3.6.1.4.1.42.2.27.8.5.1
criticality: false
base: o=sample
scope: wholeSubtree
derefAliases: neverDerefAliases
typesOnly: false
filter: (&(cn=C*)(sn=A*))
operationResponseTime: 591
timeOnWorkQ: 1
rdbmLockWaitTime: 0
clientIOTime: 180