Auditing for performance profiling

Tracing timestamps using the independent trace facility gives a detailed performance profile. However, to identify performance bottlenecks during operation execution, you can also check the audit log for the summary figures indicating performance hotspots. These hotspots are best provided as a summary. For instance, the operation response time, time spent in worker queue, the accumulated RDBM lock wait times, and time spent in client I/O per operation. The following hotspots are identified for auditing:

• When an operation has to wait in the worker thread queue for a long time before the worker thread actually starts executing the operation.
• The time spent for cache contention inside the backend needs to be tracked.
• The time spent in handling client I/O, that is, the time 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.

If the “ibm-auditPerformance” field is enabled, that is, set to ‘true’, in audit record section four performance data fields are audited: operationResponseTime, timeOnWorkQ, rdbmLockWaitTime, and clientIOTime. The value of these performance data fields is in milliseconds. The performance data fields are described here:

• operationResponseTime – This field 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 – This field 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 - This field 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 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: Starting with the IBM® Security Directory Server 6.3 release, attribute cache is deprecated. Going forward, users should must avoid using attribute cache.
  • Deadlock detector
  • RDBM locks
• clientIOTime – This field 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 and is updated on receiving the complete BER for operation request and on successfully returning the response BER message for the operation.

The following example shows the audit version 3 format for a search operation issued when ibm-auditPerformance is enabled:

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