[Freeipa-users] IPA Load Problems?

John Moyer john.moyer at digitalreasoning.com
Fri Aug 30 20:34:39 UTC 2013


I put the output in a log and did some command line magic.   It doesn't look bad at all. Highest Etime was 6. 

cat access_output | grep Etime | sort -n | uniq -c
    225   -  Etime:                 0
     67   -  Etime:                 1
      1   -  Etime:                 11
    138   -  Etime:                 2
     74   -  Etime:                 3
     35   -  Etime:                 4
      7   -  Etime:                 5
      4   -  Etime:                 6



Thanks, 
_____________________________________________________
John Moyer
Director, IT Operations
Digital Reasoning Systems, Inc.
John.Moyer at digitalreasoning.com
Office:	703.678.2311
Mobile:	240.460.0023
Fax:		703.678.2312
www.digitalreasoning.com

On Aug 30, 2013, at 4:25 PM, Rich Megginson <rmeggins at redhat.com> wrote:

> On 08/30/2013 02:10 PM, John Moyer wrote:
>> So I'm trying to focus on just one use case having the performance issues.  I figured out my JIRA server does a sync against this which brings it to it's knees.   It takes it 900 seconds to complete the sync and seems to go through every group and user on the machine.  I have the base for the user group set to cn=users,cn=accounts,dc=example,dc=com and the groups to cn=groups,cn=accounts,dc=example,dc=com.   This sync took around 60 seconds off my openldap server I had before this.  Any suggestions what to look at? 
> 
> The access log should have an operation which has etime=900 (or at least a very high etime)
> 
> If you do logconv.pl -V it will print out a lot of information, including the highest etimes.  You can then use this report to look at the access logs to find out exactly which operations had these high etimes.
> 
>>    
>> 
>> 
>> Thanks, 
>> _____________________________________________________
>> John Moyer
>> Director, IT Operations
>> Digital Reasoning Systems, Inc.
>> John.Moyer at digitalreasoning.com
>> Office: 703.678.2311
>> Mobile: 240.460.0023
>> Fax: 703.678.2312
>> www.digitalreasoning.com
>> 
>> On Aug 30, 2013, at 3:49 PM, John Moyer <john.moyer at digitalreasoning.com> wrote:
>> 
>>> I'm sorry that was my top unique filter list not my unindexed list.  Please disregard my last email. 
>>> 
>>> 
>>> Thanks, 
>>> _____________________________________________________
>>> John Moyer
>>> Director, IT Operations
>>> Digital Reasoning Systems, Inc.
>>> John.Moyer at digitalreasoning.com
>>> Office: 703.678.2311
>>> Mobile: 240.460.0023
>>> Fax: 703.678.2312
>>> www.digitalreasoning.com
>>> 
>>> On Aug 30, 2013, at 3:47 PM, John Moyer <john.moyer at digitalreasoning.com> wrote:
>>> 
>>>> If objectclass eq is already indexed how are these on my top unindexed list?   Wouldn't objectclass eq cover this (objectclass=inetorgperson)? and the third and fourth entry?   I apologize if I'm way off as I am new to the intricacies of LDAP indexing. 
>>>> 
>>>> 
>>>> 
>>>> Thanks, 
>>>> _____________________________________________________
>>>> John Moyer
>>>> Director, IT Operations
>>>> 
>>>> On Aug 30, 2013, at 3:41 PM, Rich Megginson <rmeggins at redhat.com> wrote:
>>>> 
>>>>> On 08/30/2013 01:31 PM, John Moyer wrote:
>>>>>> Rob or anyone else,  
>>>>>> 
>>>>>> So while struggling along on this server I just grabbed the logs off it and ran that log program with the options you suggested.   There are a lot of unindexed requests.   These are the top issues I've removed the one username that showed up.   
>>>>>> 
>>>>>> So just to double check what I'm thinking.   I need to create three indexes
>>>>>>  1. objectclass pres
>>>>> No, do not create this one
>>>>>>  2. objectclass eq
>>>>> This should already be indexed
>>>>>>  3. uid pres 
>>>>> I suppose the UI might be doing this search?
>>>>>> 
>>>>>> Please let me know if I'm reading this correctly or if I'm way off?   
>>>>>> 
>>>>>> 
>>>>>> 7337            (objectclass=inetorgperson)
>>>>>> 4597            (objectclass=*)
>>>>>> 4560            (&(objectclass=inetorgperson)(uid=senior.developer.login))
>>>>>> 307             (objectclass=krbticketpolicyaux)
>>>>>> 292             (uid=*)
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> Thanks, 
>>>>>> _____________________________________________________
>>>>>> John Moyer
>>>>>> Director, IT Operations
>>>>>> Digital Reasoning Systems, Inc.
>>>>>> John.Moyer at digitalreasoning.com
>>>>>> Office: 703.678.2311
>>>>>> Mobile: 240.460.0023
>>>>>> Fax: 703.678.2312
>>>>>> www.digitalreasoning.com
>>>>>> 
>>>>>> On Aug 28, 2013, at 11:40 AM, Rob Crittenden <rcritten at redhat.com> wrote:
>>>>>> 
>>>>>>> John Moyer wrote:
>>>>>>>> So this method of search logs is great, and it shows some indexes that would likely highly increase efficiency with my usage.   So, are there instructions how to do that?  or do you know off hand how to do that?
>>>>>>> 
>>>>>>> I'd start with https://access.redhat.com/site/documentation/en-US/Red_Hat_Directory_Server/9.0/html-single/Administration_Guide/index.html#Managing_Indexes-About_Indexes
>>>>>>> 
>>>>>>> Note that you'll want to create the same index on all hosts. This configuration is not replicated.
>>>>>>> 
>>>>>>> You can see the ones we create in /usr/share/ipa/indices.ldif and /usr/share/ipa/updates/20-indices.update
>>>>>>> 
>>>>>>> rob
>>>>>>> 
>>>>>>>> 
>>>>>>>> 
>>>>>>>> Thanks,
>>>>>>>> _____________________________________________________
>>>>>>>> John Moyer
>>>>>>>> Director, IT Operations
>>>>>>>> Digital Reasoning Systems, Inc.
>>>>>>>> John.Moyer at digitalreasoning.com
>>>>>>>> Office:
>>>>>>>>                                               703.678.2311
>>>>>>>> Mobile:
>>>>>>>>                                               240.460.0023
>>>>>>>> Fax:
>>>>>>>>                                               
>>>>>>>>                                               703.678.2312
>>>>>>>> www.digitalreasoning.com
>>>>>>>> 
>>>>>>>> On Aug 27, 2013, at 4:45 PM, Rob Crittenden <rcritten at redhat.com> wrote:
>>>>>>>> 
>>>>>>>>> John Moyer wrote:
>>>>>>>>>> Wow, this is quite insightful, this is the output from that, it looks like there aren't many unindexed searches (319 doesn't seem like a lot to me at least).  Do you have any suggestions from this output?
>>>>>>>>> 
>>>>>>>>> There are a slew of options you can provide to logconv.pl. I typically use logconv.pl -ula /var/log/dirsrv/slapd-EXAMPLE-COM/access when doing search analysis.
>>>>>>>>> 
>>>>>>>>> rob
>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> Start of Log:    27/Aug/2013:02:36:08
>>>>>>>>>> End of Log:      27/Aug/2013:12:17:15
>>>>>>>>>> 
>>>>>>>>>> Processed Log Time:  9 Hours, 41 Minutes, 7 Seconds
>>>>>>>>>> 
>>>>>>>>>> Restarts:                     2
>>>>>>>>>> Total Connections:            45224
>>>>>>>>>> SSL Connections:              44735
>>>>>>>>>> Peak Concurrent Connections:  76
>>>>>>>>>> Total Operations:             132568
>>>>>>>>>> Total Results:                132737
>>>>>>>>>> Overall Performance:          100.0%
>>>>>>>>>> 
>>>>>>>>>> Searches:                     61318      (1.76/sec)  (105.52/min)
>>>>>>>>>> Modifications:                277        (0.01/sec)  (0.48/min)
>>>>>>>>>> Adds:                         10         (0.00/sec)  (0.02/min)
>>>>>>>>>> Deletes:                      12         (0.00/sec)  (0.02/min)
>>>>>>>>>> Mod RDNs:                     0          (0.00/sec)  (0.00/min)
>>>>>>>>>> Compares:                     0          (0.00/sec)  (0.00/min)
>>>>>>>>>> Binds:                        62143      (1.78/sec)  (106.94/min)
>>>>>>>>>> 
>>>>>>>>>> Proxied Auth Operations:      0
>>>>>>>>>> Persistent Searches:          3
>>>>>>>>>> Internal Operations:          0
>>>>>>>>>> Entry Operations:             0
>>>>>>>>>> Extended Operations:          8808
>>>>>>>>>> Abandoned Requests:           0
>>>>>>>>>> Smart Referrals Received:     0
>>>>>>>>>> 
>>>>>>>>>> VLV Operations:               0
>>>>>>>>>> VLV Unindexed Searches:       0
>>>>>>>>>> SORT Operations:              353
>>>>>>>>>> 
>>>>>>>>>> Entire Search Base Queries:   106
>>>>>>>>>> Unindexed Searches:           319
>>>>>>>>>> 
>>>>>>>>>> FDs Taken:                    45262
>>>>>>>>>> FDs Returned:                 45210
>>>>>>>>>> Highest FD Taken:             139
>>>>>>>>>> 
>>>>>>>>>> Broken Pipes:                 0
>>>>>>>>>> Connections Reset By Peer:    0
>>>>>>>>>> Resource Unavailable:         0
>>>>>>>>>> 
>>>>>>>>>> Binds:                        62143
>>>>>>>>>> Unbinds:                      44539
>>>>>>>>>> 
>>>>>>>>>>  LDAP v2 Binds:               2
>>>>>>>>>>  LDAP v3 Binds:               62141
>>>>>>>>>>  SSL Client Binds:            0
>>>>>>>>>>  Failed SSL Client Binds:     0
>>>>>>>>>>  SASL Binds:                  1466
>>>>>>>>>>   1458  GSSAPI
>>>>>>>>>>   8     EXTERNAL
>>>>>>>>>> 
>>>>>>>>>>  Directory Manager Binds:     10
>>>>>>>>>>  Anonymous Binds:             1476
>>>>>>>>>>  Other Binds:                 60657
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> Thanks,
>>>>>>>>>> _____________________________________________________
>>>>>>>>>> John Moyer
>>>>>>>>>> Director, IT Operations
>>>>>>>>>> On Aug 27, 2013, at 1:13 PM, Rob Crittenden <rcritten at redhat.com> wrote:
>>>>>>>>>> 
>>>>>>>>>>> John Moyer wrote:
>>>>>>>>>>>> Is there any way to see what fields are index'ed?
>>>>>>>>>>> 
>>>>>>>>>>> $ ldapsearch -LLL -D 'cn=directory manager' -W -x -b 'cn=index,cn=userRoot,cn=ldbm database,cn=plugins,cn=config'
>>>>>>>>>>> 
>>>>>>>>>>> Your best bet is to use the logconv.pl tool to examine your logs.
>>>>>>>>>>> 
>>>>>>>>>>> rob
>>>>>>>>>>> 
>>>>>>>>>>>> 
>>>>>>>>>>>> Thanks,
>>>>>>>>>>>> _____________________________________________________
>>>>>>>>>>>> John Moyer
>>>>>>>>>>>> Director, IT Operations
>>>>>>>>>>>> Digital Reasoning Systems, Inc.
>>>>>>>>>>>> John.Moyer at digitalreasoning.com
>>>>>>>>>>>> Office: 703.678.2311
>>>>>>>>>>>> Mobile: 240.460.0023
>>>>>>>>>>>> Fax: 
>>>>>>>>>>>>                                                       703.678.2312
>>>>>>>>>>>> www.digitalreasoning.com
>>>>>>>>>>>> 
>>>>>>>>>>>> On Aug 27, 2013, at 10:36 AM, John Moyer <john.moyer at digitalreasoning.com> wrote:
>>>>>>>>>>>> 
>>>>>>>>>>>>> That looks like the output I just got shown below:
>>>>>>>>>>>>> 
>>>>>>>>>>>>> 
>>>>>>>>>>>>> dn: cn=mapping tree,cn=config
>>>>>>>>>>>>> 
>>>>>>>>>>>>> dn: cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config
>>>>>>>>>>>>> 
>>>>>>>>>>>>> dn: cn=replica,cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config
>>>>>>>>>>>>> 
>>>>>>>>>>>>> dn: cn=meToipa2.example.com,cn=replica,cn=dc\3Dexample\
>>>>>>>>>>>>> 2Cdc\3Dcom,cn=mapping tree,cn=config
>>>>>>>>>>>>> nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial
>>>>>>>>>>>>>  entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount
>>>>>>>>>>>>> nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblasts
>>>>>>>>>>>>> uccessfulauth krblastfailedauth krbloginfailedcount
>>>>>>>>>>>>> 
>>>>>>>>>>>>> 
>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>> _____________________________________________________
>>>>>>>>>>>>> John Moyer
>>>>>>>>>>>>> Director, IT Operations
>>>>>>>>>>>>> 
>>>>>>>>>>>>> 
>>>>>>>>>>>>> On Aug 27, 2013, at 10:14 AM, Rob Crittenden <rcritten at redhat.com> wrote:
>>>>>>>>>>>>> 
>>>>>>>>>>>>>> John Moyer wrote:
>>>>>>>>>>>>>>> Ok, so we tried to implement this again, and as soon as we put on a
>>>>>>>>>>>>>>> server that authenticates heavily the IPA came to it's knees again.
>>>>>>>>>>>>>>> This time I was able to watch it closely and try to troubleshoot a lot
>>>>>>>>>>>>>>> more, and also know exactly what server caused it (Mercurial with help
>>>>>>>>>>>>>>> of bamboo).   This runs fine on a normal old openldap servers.   The
>>>>>>>>>>>>>>> user is logging in very quickly and each time it logs in I can see in
>>>>>>>>>>>>>>> the logs that the krbLastsuccessfullogin parameter (or whatever it is
>>>>>>>>>>>>>>> called) is updated over and over and over in the changelog
>>>>>>>>>>>>>>> (/var/lib/dirsrv/slapd-$instanceid/db) those logs are filling VERY
>>>>>>>>>>>>>>> quickly and then disappear fairly quickly as well.
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> Issue 1: This is causing severe disk latency which obviously slows
>>>>>>>>>>>>>>> everything down wait times were around 25%+
>>>>>>>>>>>>>>> Issue 2: These changes need to be replicated to my slave server thus
>>>>>>>>>>>>>>> adding to the mess
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> My question is, why does the IPA server fail to keep up with the load
>>>>>>>>>>>>>>> when the openLDAP server didn't have an issue.   Indexes?
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> I'm running the following:
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> CentOS release 6.4 (Final)
>>>>>>>>>>>>>>> 389-ds-base-1.2.11.15-20.el6_4.x86_64
>>>>>>>>>>>>>>> 389-ds-base-libs-1.2.11.15-20.el6_4.x86_64
>>>>>>>>>>>>>>> ipa-python-3.0.0-26.el6_4.4.x86_64
>>>>>>>>>>>>>>> ipa-admintools-3.0.0-26.el6_4.4.x86_64
>>>>>>>>>>>>>>> ipa-pki-common-theme-9.0.3-7.el6.noarch
>>>>>>>>>>>>>>> python-iniparse-0.3.1-2.1.el6.noarch
>>>>>>>>>>>>>>> ipa-server-3.0.0-26.el6_4.4.x86_64
>>>>>>>>>>>>>>> ipa-pki-ca-theme-9.0.3-7.el6.noarch
>>>>>>>>>>>>>>> ipa-server-selinux-3.0.0-26.el6_4.4.x86_64
>>>>>>>>>>>>>>> libipa_hbac-1.9.2-82.7.el6_4.x86_64
>>>>>>>>>>>>>>> ipa-client-3.0.0-26.el6_4.4.x86_64
>>>>>>>>>>>>>>> libipa_hbac-python-1.9.2-82.7.el6_4.x86_64
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> So I've implemented this server anyway (against my better judgement with
>>>>>>>>>>>>>>> these issues and just made the user that logs into mercurial a local
>>>>>>>>>>>>>>> user instead of IPA).
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> Also note before I did that for fun I implemented a RAM disk to put the
>>>>>>>>>>>>>>> change logs on, and that dropped the wait time to 0 (except bursts where
>>>>>>>>>>>>>>> it would raise to 30 to write the access log) but the CPU drove to 100%
>>>>>>>>>>>>>>> trying to keep up with the load.  I have also killed the replication as
>>>>>>>>>>>>>>> well.
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>>> Any help would be appreciated.
>>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> krblastsuccessfulauth should be excluded from replication, though I guess that doesn't prevent it from ending up in the changelog.
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> You can confirm that they are excluded by searching the agreements:
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> $ ldapsearch -LLL -x -b 'cn=mapping tree,cn=config' -D 'cn=directory manager' -W nsDS5ReplicatedAttributeList nsDS5ReplicatedAttributeListTotal
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> They should look like:
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount
>>>>>>>>>>>>>> 
>>>>>>>>>>>>>> rob
>>>>>>>>>>>>> 
>>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>> 
>>>>>>>> 
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 
>>> 
>> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130830/205da4ce/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 495 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130830/205da4ce/attachment.sig>


More information about the Freeipa-users mailing list