Chapter 7. Logging statistics per search operation

During some search operations, especially with filters such as (cn=user*), the time the server spends for receiving the tasks and then sending the result back (etime) can be very long.

Expanding the access log with information related to indexes used during search operation helps to diagnose why etime value is resource expensive.

Use the nsslapd-statlog-level attribute to enable collecting statistics, such as a number of index lookups (database read operations) and overall duration of index lookups for each search operation, with minimal impact on the server.

Prerequisites

  • You enabled access logging.

Procedure

  1. Enable search operation metrics: 

    # dsconf -D "cn=Directory Manager" ldap://server.example.com config replace nsslapd-statlog-level=1

  2. Restart the instance: 

    # dsctl instance_name restart

Verification

  1. Perform a search operation: 

    # ldapsearch -D "cn=Directory Manager" -H ldap://server.example.com -b "dc=example,dc=com" -s sub -x "cn=user*"

  2. View the access log file and find the search statistics records: 

    # cat /var/log/dirsrv/slapd-instance_name/access
...
[16/Nov/2022:11:34:11.834135997 +0100] conn=1 op=73 SRCH base="dc=example,dc=com" scope=2 filter="(cn=user)"* attrs=ALL
[16/Nov/2022:11:34:11.835750508 +0100] conn=1 op=73 STAT read index: attribute=objectclass key(eq)=referral --> count 0
[16/Nov/2022:11:34:11.836648697 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=er_ --> count 25
[16/Nov/2022:11:34:11.837538489 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=ser --> count 25
[16/Nov/2022:11:34:11.838814948 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=use --> count 25
[16/Nov/2022:11:34:11.841241531 +0100] conn=1 op=73 STAT read index: attribute=cn key(sub)=^us --> count 25
[16/Nov/2022:11:34:11.842230318 +0100] conn=1 op=73 STAT read index: duration 0.000010276
[16/Nov/2022:11:34:11.843185322 +0100] conn=1 op=73 RESULT err=0 tag=101 nentries=24 wtime=0.000078414 optime=0.001614101 etime=0.001690742
...

Additional resources

  • TBA the link to nsslapd-statlog-level description