Hi Mark, Just examining the output from logconv.pl and I’m not understanding why it’s reporting
Unindexed Search #1 (notes=A) - Date/Time: 08/Dec/2014:10:30:12 - Connection Number: 215422 - Operation Number: 2 - Etime: 1 - Nentries: 100 - IP Address: 10.7.8.105 - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) Objectclass is part of the default set of indexes: dn: cn=objectclass,cn=default indexes,cn=config,cn=ldbm database,cn=plugins,cn =config objectClass: top objectClass: nsIndex cn: objectclass nsSystemIndex: true nsIndexType: eq Trev From: <Fong>, Trevor Fong <[email protected]<mailto:[email protected]>> Reply-To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>> Date: Tuesday, December 9, 2014 at 9:14 AM To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>>, "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>> Subject: Re: [389-users] 389-ds and Multi CPU's Hi Mark, Oops – sorry about the Mike thing! I sit beside a Mike :p Oh – no notes in that search, but there are notes in the preceding and subsequent searches. It looks like it returns the first 100 results then searches for groupOfNames for each of those users, and then repeats until all 30,000 users is done: 08/Dec/2014:07:08:04 -0800] conn=130261 fd=64 slot=64 SSL connection from <ip addr 1> to <ip addr 2> [08/Dec/2014:07:08:04 -0800] conn=130261 SSL 256-bit AES [08/Dec/2014:07:08:04 -0800] conn=130261 op=0 BIND dn="<service account>" method=128 version=3 [08/Dec/2014:07:08:04 -0800] conn=130261 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="<service account>" [08/Dec/2014:07:08:04 -0800] conn=130261 op=1 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedControl" [08/Dec/2014:07:08:04 -0800] conn=130261 op=1 RESULT err=0 tag=101 nentries=1 etime=0 [08/Dec/2014:07:08:04 -0800] conn=130261 op=2 SRCH base="ou=EMPLOYEES,dc=<our dc>" scope=2 filter="(&(objectClass=inetOrgPerson))" attrs="businessCategory carLicense cn departmentNumber description destinationIndicator displayName distinguishedName employeeNumber employeeType facsimileTelephoneNumber givenName groups homePhone homePostalAddress initials internationalISDNNumber l mail manager mobile o objectClass o ou pager physicalDeliveryOfficeName postOfficeBox postalAddress postalCode preferredDeliveryMethod preferredLanguage registeredAddress roomNumber secretary seeAlso sn st street telephoneNumber teletexTerminalIdentifier telexNumber title ubcEduCwlPUID uid nsAccountLock passwordRetryCount" [08/Dec/2014:07:08:04 -0800] conn=130261 op=2 SORT cn (*) [08/Dec/2014:07:08:04 -0800] conn=130261 op=2 RESULT err=0 tag=101 nentries=100 etime=0 notes=P,A [08/Dec/2014:07:08:04 -0800] conn=130262 fd=83 slot=83 SSL connection from <ip addr 1> to <ip addr 2> [08/Dec/2014:07:08:04 -0800] conn=130262 SSL 256-bit AES [08/Dec/2014:07:08:04 -0800] conn=130262 op=0 BIND dn="<service account>" method=128 version=3 [08/Dec/2014:07:08:04 -0800] conn=130262 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="<service account>" [08/Dec/2014:07:08:04 -0800] conn=130262 op=1 SRCH base="ou=GROUPS,dc=<our dc>" scope=2 filter="(&(objectClass=groupOfNames)(member=uid=<login_x>,ou=EMPLOYEES,dc=<our dc>))" attrs="1.1" [08/Dec/2014:07:08:04 -0800] conn=130262 op=1 RESULT err=0 tag=101 nentries=5 etime=0 … <snip> [08/Dec/2014:07:08:05 -0800] conn=130262 op=100 SRCH base="ou=GROUPS,dc=<our dc>" scope=2 filter="(&(objectClass=groupOfNames)(member=uid=<login_x+100>,ou=EMPLOYEES,dc=<our dc>))" attrs="1.1" [08/Dec/2014:07:08:05 -0800] conn=130262 op=100 RESULT err=0 tag=101 nentries=3 etime=0 [08/Dec/2014:07:08:05 -0800] conn=130261 op=3 SRCH base="ou=EMPLOYEES,dc=<our dc>" scope=2 filter="(&(objectClass=inetOrgPerson))" attrs="businessCategory carLicense cn departmentNumber description destinationIndicator displayName distinguishedName employeeNumber employeeType facsimileTelephoneNumber givenName groups homePhone homePostalAddress initials internationalISDNNumber l mail manager mobile o objectClass o ou pager physicalDeliveryOfficeName postOfficeBox postalAddress postalCode preferredDeliveryMethod preferredLanguage registeredAddress roomNumber secretary seeAlso sn st street telephoneNumber teletexTerminalIdentifier telexNumber title ubcEduCwlPUID uid nsAccountLock passwordRetryCount" … <snip> [08/Dec/2014:07:08:05 -0800] conn=130261 op=3 RESULT err=0 tag=101 nentries=100 etime=0 notes=U,P Oh cool – I didn’t know about logconv.pl! Output follows. Thanks again, Trev Total Log Lines Analysed: 799338 ----------- Access Log Output ------------ Start of Logs: 08/Dec/2014:05:56:33 End of Logs: 08/Dec/2014:10:31:46 Processed Log Time: 4 Hours, 35 Minutes, 13 Seconds Restarts: 0 Total Connections: 87873 - StartTLS Connections: 0 - LDAPS Connections: 87265 - LDAPI Connections: 0 Peak Concurrent Connections: 34 Total Operations: 227313 Total Results: 227314 Overall Performance: 100.0% Searches: 109051 (6.60/sec) (396.24/min) Modifications: 28121 (1.70/sec) (102.18/min) Adds: 69 (0.00/sec) (0.25/min) Deletes: 0 (0.00/sec) (0.00/min) Mod RDNs: 0 (0.00/sec) (0.00/min) Compares: 0 (0.00/sec) (0.00/min) Binds: 85702 (5.19/sec) (311.40/min) Proxied Auth Operations: 0 Persistent Searches: 0 Internal Operations: 0 Entry Operations: 0 Extended Operations: 4370 Abandoned Requests: 0 Smart Referrals Received: 0 VLV Operations: 0 VLV Unindexed Searches: 0 VLV Unindexed Components: 0 SORT Operations: 3 Entire Search Base Queries: 0 Paged Searches: 505 Unindexed Searches: 2 Unindexed Components: 502 Unindexed Search #1 (notes=A) - Date/Time: 08/Dec/2014:10:30:12 - Connection Number: 215422 - Operation Number: 2 - Etime: 1 - Nentries: 100 - IP Address: 10.7.8.105 - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) Unindexed Search #2 (notes=A) - Date/Time: 08/Dec/2014:07:08:04 - Connection Number: 130261 - Operation Number: 2 - Etime: 0 - Nentries: 100 - IP Address: 10.7.8.105 - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) Unindexed Component #1 (notes=U) - Date/Time: 08/Dec/2014:05:56:45 - Connection Number: 129083 - Operation Number: 117 - Etime: 0 - Nentries: 100 - IP Address: Unknown_Host - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) Unindexed Component #2 (notes=U) - Date/Time: 08/Dec/2014:05:57:10 - Connection Number: 129083 - Operation Number: 122 - Etime: 0 - Nentries: 100 - IP Address: Unknown_Host - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) …<snip> Unindexed Component #502 (notes=U) - Date/Time: 08/Dec/2014:10:30:47 - Connection Number: 215422 - Operation Number: 3 - Etime: 0 - Nentries: 100 - IP Address: 10.7.8.105 - Search Base: ou=employees,dc=<our dc> - Search Scope: 2 (subtree) - Search Filter: (&(objectclass=inetorgperson)) FDs Taken: 87873 FDs Returned: 87863 Highest FD Taken: 275 Broken Pipes: 0 Connections Reset By Peer: 0 Resource Unavailable: 0 Max BER Size Exceeded: 0 Binds: 85702 Unbinds: 83924 - LDAP v2 Binds: 0 - LDAP v3 Binds: 85702 - AUTOBINDs: 0 - SSL Client Binds: 0 - Failed SSL Client Binds: 0 - SASL Binds: 0 - Directory Manager Binds: 0 - Anonymous Binds: 0 - Other Binds: 85702 ----- Connection Latency Details ----- (in seconds) <=1 2 3 4-5 6-10 11-15 >15 -------------------------------------------------------------------------- (# of connections) 87553 169 27 18 5 2 89 ----- Current Open Connection IDs ----- Conn Number: 201302 (10.7.127.250) Conn Number: 217063 (10.7.8.105) Conn Number: 217064 (10.7.8.105) Conn Number: 217061 (10.7.8.105) Conn Number: 132242 (10.7.0.52) Conn Number: 196007 (10.7.127.250) Conn Number: 196107 (10.7.127.250) Conn Number: 215425 (10.7.8.105) Conn Number: 217060 (10.7.8.105) Conn Number: 215422 (10.7.8.105) Conn Number: 207139 (10.7.127.250) Conn Number: 217062 (10.7.8.105) ----- Errors ----- err=0 224008 Successful Operations err=32 1652 No Such Object err=53 1652 Unwilling To Perform err=49 1 Invalid Credentials (Bad Password) err=65 1 Objectclass Violation ----- Top 20 Failed Logins ------ 1 uid=ehannah,ou=employees,dc=<our dc> >From the IP address(s) : 1 10.7.127.250 ----- Total Connection Codes ----- U1 83924 Cleanly Closed Connections B1 1749 Bad Ber Tag Encountered ----- Top 20 Clients ----- Number of Clients: 13 [1] Client: 10.7.8.105 83638 - Connections 83631 - U1 (Cleanly Closed Connections) [2] Client: 137.82.5.97 1652 - Connections 1652 - B1 (Bad Ber Tag Encountered) [3] Client: 142.103.218.107 1095 - Connections [4] Client: 142.103.218.106 1094 - Connections [5] Client: 10.7.127.250 112 - Connections 106 - U1 (Cleanly Closed Connections) 1 - B1 (Bad Ber Tag Encountered) [6] Client: 127.0.0.1 57 - Connections 55 - B1 (Bad Ber Tag Encountered) 2 - U1 (Cleanly Closed Connections) [7] Client: 142.103.149.136 55 - Connections 41 - B1 (Bad Ber Tag Encountered) 14 - U1 (Cleanly Closed Connections) [8] Client: 10.7.0.52 51 - Connections 50 - U1 (Cleanly Closed Connections) [9] Client: 142.103.106.141 29 - Connections 29 - U1 (Cleanly Closed Connections) [10] Client: 142.103.106.143 28 - Connections 28 - U1 (Cleanly Closed Connections) [11] Client: 142.103.106.145 23 - Connections 23 - U1 (Cleanly Closed Connections) [12] Client: 142.103.106.135 23 - Connections 23 - U1 (Cleanly Closed Connections) [13] Client: 142.103.106.142 16 - Connections 16 - U1 (Cleanly Closed Connections) ----- Top 20 Bind DN's ----- Number of Unique Bind DN's: 18 83795 uid=eldap-svciiq,ou=service accounts,ou=eldap,ou=services,dc=id,dc=ubc,dc=ca 1652 cn=bill fisher,ou=people,dc=dartware,dc=com 112 cn=directory manager 55 uid=eldap-svcvpnsync,ou=service accounts,ou=eldap,ou=services,dc=id,dc=ubc,dc=ca 51 cn=replication manager,cn=config 6 uid=alexnam,ou=employees,dc=<our dc> 4 uid=priyanth,ou=employees,dc=<our dc> 4 uid=arsuther,ou=employees,dc=<our dc> 4 uid=huynhh,ou=employees,dc=<our dc> 3 uid=ehannah,ou=employees,dc=<our dc> 2 uid=andyfehr,ou=employees,dc=<our dc> 2 uid=bullfrog,ou=employees,dc=<our dc> 2 uid=eddiefok,ou=employees,dc=<our dc> 2 uid=elyoung,ou=employees,dc=<our dc> 2 uid=elainez,ou=employees,dc=<our dc> 2 uid=flokam,ou=employees,dc=<our dc> 2 uid=mailvaga,ou=employees,dc=<our dc> 2 uid=sjones,ou=employees,dc=<our dc> ----- Top 20 Search Bases ----- Number of Unique Search Bases: 27876 78174 ou=groups,dc=<our dc> 1652 ou=people,dc=dartware,dc=com 676 ou=employees,dc=<our dc> 312 ou=people,dc=<our dc> 220 cn=mapping tree,cn=config 124 root dse 13 cn=idm-status-activeemployees,ou=idm,ou=role,ou=groups,dc=<our dc> 3 uid=jbartnik,ou=employees,dc=<our dc> 2 uid=rodsprus,ou=employees,dc=<our dc> 2 uid=zanottic,ou=employees,dc=<our dc> 2 uid=ttucker,ou=employees,dc=<our dc> 2 uid=dbilczuk,ou=employees,dc=<our dc> 2 uid=phys2012,ou=employees,dc=<our dc> 2 uid=ydeng,ou=employees,dc=<our dc> 2 uid=natcrang,ou=employees,dc=<our dc> 2 uid=lillaroy,ou=employees,dc=<our dc> 2 uid=wpr8847,ou=employees,dc=<our dc> 1 uid=ap8040,ou=employees,dc=<our dc> 1 uid=asr5,ou=employees,dc=<our dc> 1 uid=belzberg,ou=employees,dc=<our dc> ----- Top 20 Search Filters ----- Number of Unique Search Filters: 30968 28016 (objectclass=*) 1652 (cn=bill fisher) 504 (&(objectclass=inetorgperson)) 55 (cn=eldap3*) 55 (cn=eldap5*) 55 (cn=eldap4*) 55 (cn=eldap2*) 6 (&(objectclass=groupofnames)(member=uid=alexnam,ou=employees,dc=<our dc>)) 5 (&(objectclass=groupofnames)(member=uid=ehannah,ou=employees,dc=<our dc>)) 5 (&(objectclass=groupofnames)(member=uid=priyanth,ou=employees,dc=<our dc>)) 5 (&(objectclass=groupofnames)(member=uid=arsuther,ou=employees,dc=<our dc>)) 4 (&(objectclass=groupofnames)(member=uid=ydeng,ou=employees,dc=<our dc>)) 4 (&(objectclass=inetorgperson)(ubceducwlloginkey=<login key 1>)) 4 (&(objectclass=groupofnames)(member=uid=elyoung,ou=employees,dc=<our dc>)) 4 (&(objectclass=groupofnames)(member=uid=zanottic,ou=employees,dc=<our dc>)) 4 (&(uid=devlin11)) 4 (&(objectclass=groupofnames)(member=uid=huynhh,ou=employees,dc=<our dc>)) 4 (&(objectclass=inetorgperson)(ubceducwlloginkey=<login key 2>)) 4 (&(objectclass=groupofnames)(member=uid=lillaroy,ou=employees,dc=<our dc>)) 4 (&(objectclass=groupofnames)(member=uid=rodsprus,ou=employees,dc=<our dc>)) ----- Top 20 Most Frequent etimes ----- 219090 etime=0 8202 etime=1 20 etime=2 1 etime=147 1 etime=135 ----- Top 20 Longest etimes ----- etime=147 1 etime=135 1 etime=2 20 etime=1 8202 etime=0 219090 ----- Top 20 Largest nentries ----- nentries=100 502 nentries=34 1 nentries=27 1 nentries=26 1 nentries=7 3 nentries=6 9 nentries=5 85 nentries=4 334 nentries=3 1957 nentries=2 6701 nentries=1 85038 nentries=0 14420 ----- Top 20 Most returned nentries ----- 85038 nentries=1 14420 nentries=0 6701 nentries=2 1957 nentries=3 502 nentries=100 334 nentries=4 85 nentries=5 9 nentries=6 3 nentries=7 1 nentries=26 1 nentries=27 1 nentries=34 ----- Extended Operations ----- 2185 2.16.840.1.113730.3.5.12 DS90 Start Replication Request 2185 2.16.840.1.113730.3.5.5 End Replication Request (incremental update) ----- Top 20 Most Requested Attributes ----- 78174 1.1 56799 o 28712 description 28712 cn 28712 nsAccountLock 28711 givenName 28711 ubcEduCwlPUID 28711 uid 28711 displayName 28711 employeeNumber 28711 mail 28711 objectClass 28711 sn 28400 ou 28400 passwordRetryCount 28400 distinguishedName 28399 businessCategory 28399 employeeType 28399 facsimileTelephoneNumber 28399 groups ----- Recommendations ----- 1. You have unindexed searches, this can be caused from a search on an unindexed attribute, or your returned results exceeded the allidsthreshold. Unindexed searches are not recommended. To refuse unindexed searches, switch 'nsslapd-require-index' to 'on' under your database entry (e.g. cn=UserRoot,cn=ldbm database,cn=plugins,cn=config). 2. You have unindexed components, this can be caused from a search on an unindexed attribute, or your returned results exceeded the allidsthreshold. Unindexed components are not recommended. To refuse unindexed searches, switch 'nsslapd-require-index' to 'on' under your database entry (e.g. cn=UserRoot,cn=ldbm database,cn=plugins,cn=config). Cleaning up temp files... Done. From: Mark Reynolds <[email protected]<mailto:[email protected]>> Reply-To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>> Date: Tuesday, December 9, 2014 at 7:25 AM To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>>, Trevor Fong <[email protected]<mailto:[email protected]>> Subject: Re: [389-users] 389-ds and Multi CPU's On 12/08/2014 05:43 PM, Fong, Trevor wrote: Hi Mike, It's Mark :-) I get that a lot for some reason. Thanks for the reply. The typical result of the result is: [08/Dec/2014:07:08:04 -0800] conn=130262 op=1 RESULT err=0 tag=101 nentries=5 etime=0 Yeah this looks fine. There are no notes=A/notes=U in the results. Do you mean in the entire access log, or just for that search? Can you run logconv.pl and post the results? "logconv.pl -V <access logs>" Thanks Trevor, Mark Objectclass and member are both indexed. There were 30,000-odd searches on conn=130262, which took 34 mins. Thanks, Trev From: Mark Reynolds <[email protected]<mailto:[email protected]>> Reply-To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>> Date: Monday, December 8, 2014 at 11:29 AM To: "[email protected]<mailto:[email protected]>" <[email protected]<mailto:[email protected]>>, Trevor Fong <[email protected]<mailto:[email protected]>> Subject: Re: [389-users] 389-ds and Multi CPU's On 12/08/2014 02:08 PM, Fong, Trevor wrote: Hi Everyone, We’ve inherited a 389-ds system (1.2.11.15-48.el6_6) that is running on a VM provisioned with a single CPU. We have been experiencing high CPU with a client that connects with a single connection, and then runs large amounts of queries of the form: SRCH base="ou=GROUPS,dc=<our dc>" scope=2 filter="(&(objectClass=groupOfNames)(member=uid=<loginname>,ou=EMPLOYEES,<our dc>))" attrs=“1.1" Trevor, >From the access log, what is the result of this search? etime? It there a >notes=U/notes=A in the result? It could be an unindexed search which would >cause the high CPU. Thanks, Mark We’re wondering if adding extra CPU’s to the vm will make things better. The original engineer noted that at the time of implementation, he had come across some notes that indicated that the underlying process was single threaded and adding extra CPU’s would not make any improvement; in fact, on heavily loaded vm infrastructure like ours, may make things worse as the the vm would have to wait for the CPU to become available. Is this still true? Thanks a lot, Trev -- 389 users mailing list [email protected]<mailto:[email protected]>https://admin.fedoraproject.org/mailman/listinfo/389-users -- 389 users mailing list [email protected]<mailto:[email protected]>https://admin.fedoraproject.org/mailman/listinfo/389-users
-- 389 users mailing list [email protected] https://admin.fedoraproject.org/mailman/listinfo/389-users
