#6722 Unindexed LDAP searches
Closed: fixed by cheimes. Opened by cheimes.

Here is another ticket related to performance.

Today Nathan suggested that I use logconv.pl to analyze 389-DS's logs for unindexed queries. I found a bunch of queries that could benefit from an index. The majority of missing indexes seem to be related to Dogtag PKI. Some of them are FreeIPA. Dogtag issue is https://pagure.io/dogtagpki/issue/2603 .

# logconv.pl -U /var/log/dirsrv/slapd-IPA-EXAMPLE/access*   
Access Log Analyzer 8.2
Command: logconv.pl /var/log/dirsrv/slapd-IPA-EXAMPLE/access /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170224-165443 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170225-165520 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170226-165524 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170227-165529 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170228-170026 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170301-170120 /var/log/dirsrv/slapd-IPA-EXAMPLE/access.rotationinfo
Processing 7 Access Log(s)...
[007] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170224-165443  size (bytes):      7348817
     25000 Lines Processed          4601976 of      7348817 bytes (62.622%)
[006] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170225-165520  size (bytes):      4963213
     25000 Lines Processed          4650135 of      4963213 bytes (93.692%)
[005] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170226-165524  size (bytes):      3669580
[004] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170227-165529  size (bytes):      4170095
[003] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170228-170026  size (bytes):      5539548
[002] /var/log/dirsrv/slapd-IPA-EXAMPLE/access.20170301-170120  size (bytes):      2769122
[001] /var/log/dirsrv/slapd-IPA-EXAMPLE/access  size (bytes):      1554424
Total Log Lines Analysed:  142232
----------- Access Log Output ------------
Start of Logs:    24/Feb/2017:16:54:45.321852489
End of Logs:      02/Mar/2017:18:14:40.260858057
Processed Log Time:  8 Days, 1 Hours, 19 Minutes, 54.938998784 Seconds
Restarts:                     18
 Secure Protocol Versions:
  - TLS1.2 client bound as uid=pkidbuser,ou=people,o=ipaca - 107
  - TLS1.2 128-bit AES; client CN=CA Subsystem,O=IPA.EXAMPLE; issuer CN=Certificate Authority,O=IPA.EXAMPLE - 107
  - TLS1.2 128-bit AES-GCM - 41
  - TLS1.2 128-bit AES - 74
Peak Concurrent Connections:  178
Total Operations:             67324
Total Results:                65446
Overall Performance:          97.2%
Total Connections:            2715          (0.00/sec)  (0.23/min)
 - LDAP Connections:          2183          (0.00/sec)  (0.19/min)
 - LDAPI Connections:         321           (0.00/sec)  (0.03/min)
 - LDAPS Connections:         211           (0.00/sec)  (0.02/min)
 - StartTLS Extended Ops:     14            (0.00/sec)  (0.00/min)
Searches:                     48715         (0.07/sec)  (4.20/min)
Modifications:                2791          (0.00/sec)  (0.24/min)
Adds:                         6017          (0.01/sec)  (0.52/min)
Deletes:                      42            (0.00/sec)  (0.00/min)
Mod RDNs:                     9             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        5963          (0.01/sec)  (0.51/min)
Proxied Auth Operations:      0
Persistent Searches:          48
Internal Operations:          0
Entry Operations:             0
Extended Operations:          2245
Abandoned Requests:           0
Smart Referrals Received:     0
VLV Operations:               1542
VLV Unindexed Searches:       0
VLV Unindexed Components:     1030
SORT Operations:              534
Entire Search Base Queries:   36
Paged Searches:               3537
Unindexed Searches:           0
Unindexed Components:         292
  Unindexed Component Summary - 292 total unindexed components
  -  Unindexed Filters:   Filter:   (description=2;7;cn=certificate authority,o=ipa.example;cn=ipa ra,o=ipa.example) (occurrences 133)
                          - Bind DN:  cn=directory manager (binds  133)
  -  Unindexed Filters:   Filter:   (&(objectclass=ipaconfigobject)(ipaconfigstring=enabledservice)(cn=kra)) (occurrences 58)
                          - Bind DN:   (binds  58)
  -  Unindexed Filters:   Filter:   (&(ipakeyusage=digitalsignature)(memberprincipal=host/replica1.ipa.example@ipa.example)) (occurrences 20)
                          - Bind DN:  cn=directory manager (binds  20)
  -  Unindexed Filters:   Filter:   (&(ipakeyusage=dataencipherment)(memberprincipal=host/replica1.ipa.example@ipa.example)) (occurrences 20)
                          - Bind DN:  cn=directory manager (binds  20)
  -  Unindexed Filters:   Filter:   (&(objectclass=ipaconfigobject)(ipaconfigstring=enabledservice)(cn=ca)) (occurrences 14)
                          - Bind DN:   (binds  14)
  -  Unindexed Filters:   Filter:   (objectclass=*) (occurrences 10)
                          - Bind DN:  cn=directory manager (binds  10)
  -  Unindexed Filters:   Filter:   (cacertificate;binary=*) (occurrences 8)
                          - Bind DN:   (binds  8)
  -  Unindexed Filters:   Filter:   (ipaconfigstring=enabledservice) (occurrences 5)
                          - Bind DN:  cn=directory manager (binds  5)
  -  Unindexed Filters:   Filter:   (&(automountkey=*)(objectclass=automount)) (occurrences 4)
                          - Bind DN:   (binds  4)
  -  Unindexed Filters:   Filter:   (&(requeststate=approved)(requestid=*)) (occurrences 3)
                          - Bind DN:  cn=directory manager (binds  3)
  -  Unindexed Filters:   Filter:   (dnahostname=master.ipa.example) (occurrences 2)
                          - Bind DN:  cn=directory manager (binds  2)
  -  Unindexed Filters:   Filter:   (&(automountmapname=auto.direct)(objectclass=automountmap)) (occurrences 2)
                          - Bind DN:   (binds  2)
  -  Unindexed Filters:   Filter:   (&(automountmapname=auto.master)(objectclass=automountmap)) (occurrences 2)
                          - Bind DN:   (binds  2)
  -  Unindexed Filters:   Filter:   (description=2;6;cn=certificate authority,o=ipa.example;cn=ipa-ca-agent,o=ipa.example) (occurrences 2)
                          - Bind DN:  cn=directory manager (binds  2)
  -  Unindexed Filters:   Filter:   (&(|(sshfprecord=*replica1*)(hiprecord=*replica1*)(spfrecord=*replica1*)(kxrecord=*replica1*)(nxtrecord=*replica1*)(mxrecord=*replica1*)(aaaarecord=*replica1*)(mdrecord=*replica1*)(arecord=*replica1*)(dlvrecord=*replica1*)(tlsarecord=*replica1*)(ptrrecord=*replica1*)(sigrecord=*replica1*)(idnsname=*replica1*)(afsdbrecord=*replica1*)(aplrecord=*replica1*)(urirecord=*replica1*)(naptrrecord=*replica1*)(nsrecord=*replica1*)(locrecord=*replica1*)(dnamerecord=*replica1*)(rprecord=*replica1*)(dhcidrecord=*replica1*)(ipseckeyrecord=*replica1*)(rrsigrecord=*replica1*)(hinforecord=*replica1*)(cnamerecord=*replica1*)(certrecord=*replica1*)(srvrecord=*replica1*)(dsrecord=*replica1*)(txtrecord=*replica1*)(nsecrecord=*replica1*)(a6record=*replica1*)(keyrecord=*replica1*)(minforecord=*replica1*))(&(objectclass=top)(objectclass=idnsrecord))) (occurrences 2)
                          - Bind DN:  cn=directory manager (binds  2)
  -  Unindexed Filters:   Filter:   (nsrecord=replica1.ipa.example.) (occurrences 1)
                          - Bind DN:  cn=directory manager (binds  1)
  -  Unindexed Filters:   Filter:   (memberprincipal=*/replica1.ipa.example@ipa.example) (occurrences 1)
                          - Bind DN:  cn=directory manager (binds  1)
  -  Unindexed Filters:   Filter:   (|(ipaconfigstring=ipaca)(ipaconfigstring=compatca)) (occurrences 1)
                          - Bind DN:  cn=directory manager (binds  1)
  -  Unindexed Filters:   Filter:   (dnahostname=replica1.ipa.example) (occurrences 1)
                          - Bind DN:  cn=directory manager (binds  1)
  -  Unindexed Filters:   Filter:   (ipacertsubject=cn=certificate authority,o=ipa.example) (occurrences 1)
                          - Bind DN:  cn=directory manager (binds  1)
  -  Unindexed Filters:   Filter:   (&(ipserviceport=659)(ipserviceprotocol=udp)(objectclass=ipservice)) (occurrences 1)
                          - Bind DN:   (binds  1)
  -  Unindexed Filters:   Filter:   (&(ipserviceport=936)(ipserviceprotocol=udp)(objectclass=ipservice)) (occurrences 1)
                          - Bind DN:   (binds  1)
  -  Unindexed Bind DNs:  Bind DN:  cn=directory manager (binds 202)
                          - Unindexed Filter: (ipacertsubject=cn=certificate authority,o=ipa.example) (occurrances 1)
                          - Unindexed Filter: (|(ipaconfigstring=ipaca)(ipaconfigstring=compatca)) (occurrances 1)
                          - Unindexed Filter: (memberprincipal=*/replica1.ipa.example@ipa.example) (occurrances 1)
                          - Unindexed Filter: (dnahostname=replica1.ipa.example) (occurrances 1)
                          - Unindexed Filter: (nsrecord=replica1.ipa.example.) (occurrances 1)
                          - Unindexed Filter: (dnahostname=master.ipa.example) (occurrances 2)
                          - Unindexed Filter: (&(|(sshfprecord=*replica1*)(hiprecord=*replica1*)(spfrecord=*replica1*)(kxrecord=*replica1*)(nxtrecord=*replica1*)(mxrecord=*replica1*)(aaaarecord=*replica1*)(mdrecord=*replica1*)(arecord=*replica1*)(dlvrecord=*replica1*)(tlsarecord=*replica1*)(ptrrecord=*replica1*)(sigrecord=*replica1*)(idnsname=*replica1*)(afsdbrecord=*replica1*)(aplrecord=*replica1*)(urirecord=*replica1*)(naptrrecord=*replica1*)(nsrecord=*replica1*)(locrecord=*replica1*)(dnamerecord=*replica1*)(rprecord=*replica1*)(dhcidrecord=*replica1*)(ipseckeyrecord=*replica1*)(rrsigrecord=*replica1*)(hinforecord=*replica1*)(cnamerecord=*replica1*)(certrecord=*replica1*)(srvrecord=*replica1*)(dsrecord=*replica1*)(txtrecord=*replica1*)(nsecrecord=*replica1*)(a6record=*replica1*)(keyrecord=*replica1*)(minforecord=*replica1*))(&(objectclass=top)(objectclass=idnsrecord))) (occurrances 2)
                          - Unindexed Filter: (description=2;6;cn=certificate authority,o=ipa.example;cn=ipa-ca-agent,o=ipa.example) (occurrances 2)
                          - Unindexed Filter: (&(requeststate=approved)(requestid=*)) (occurrances 3)
                          - Unindexed Filter: (ipaconfigstring=enabledservice) (occurrances 5)
                          - Unindexed Filter: (objectclass=*) (occurrances 10)
                          - Unindexed Filter: (&(ipakeyusage=dataencipherment)(memberprincipal=host/replica1.ipa.example@ipa.example)) (occurrances 20)
                          - Unindexed Filter: (&(ipakeyusage=digitalsignature)(memberprincipal=host/replica1.ipa.example@ipa.example)) (occurrances 20)
                          - Unindexed Filter: (description=2;7;cn=certificate authority,o=ipa.example;cn=ipa ra,o=ipa.example) (occurrances 133)
  -  Unindexed Bind DNs:  Bind DN:   (binds 90)
                          - Unindexed Filter: (&(ipserviceport=659)(ipserviceprotocol=udp)(objectclass=ipservice)) (occurrances 1)
                          - Unindexed Filter: (&(ipserviceport=936)(ipserviceprotocol=udp)(objectclass=ipservice)) (occurrances 1)
                          - Unindexed Filter: (&(automountmapname=auto.direct)(objectclass=automountmap)) (occurrances 2)
                          - Unindexed Filter: (&(automountmapname=auto.master)(objectclass=automountmap)) (occurrances 2)
                          - Unindexed Filter: (&(automountkey=*)(objectclass=automount)) (occurrances 4)
                          - Unindexed Filter: (cacertificate;binary=*) (occurrances 8)
                          - Unindexed Filter: (&(objectclass=ipaconfigobject)(ipaconfigstring=enabledservice)(cn=ca)) (occurrances 14)
                          - Unindexed Filter: (&(objectclass=ipaconfigobject)(ipaconfigstring=enabledservice)(cn=kra)) (occurrances 58)
FDs Taken:                    3036
FDs Returned:                 2861
Highest FD Taken:             162
Broken Pipes:                 0
Connections Reset By Peer:    0
Resource Unavailable:         0
Max BER Size Exceeded:        0
Binds:                        5963
Unbinds:                      2689
 - LDAP v2 Binds:             45
 - LDAP v3 Binds:             5644
 - AUTOBINDs:                 274
 - SSL Client Binds:          0
 - Failed SSL Client Binds:   0
 - SASL Binds:                5575
    GSSAPI - 5194
    EXTERNAL - 381
 - Directory Manager Binds:   3
 - Anonymous Binds:           5306
 - Other Binds:               654

Triage notes:

  • mbabinsk: 4.6, most of those attributes are unindexed forever IMO
  • Ludwig: indexes can generate overhead as well, only if real slow search do it

Metadata Update from @pvoborni:
- Custom field keywords adjusted to performance
- Issue set to the milestone: FreeIPA 4.7

Metadata Update from @rcritten:
- Issue set to the milestone: FreeIPA 4.7.1 (was: FreeIPA 4.7)

FreeIPA 4.7 has been released, moving to FreeIPA 4.7.1 milestone

All critical cases of unindexed searches have been resolved in issues #7803, #7797, #7792, #7790, and #7787.

Metadata Update from @cheimes:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
- Issue tagged with: performance

Metadata