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:
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