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.
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
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
389-users@xxxxxxxxxxxxxxxxxxxxxxxhttps://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
389-users@xxxxxxxxxxxxxxxxxxxxxxxhttps://admin.fedoraproject.org/mailman/listinfo/389-users