[Freeipa-devel] slow response

Wed Aug 1 19:50:37 UTC 2012

On 08/01/2012 01:34 PM, Loris Santamaria wrote:
> El mié, 01-08-2012 a las 09:58 -0600, Rich Megginson escribió:
>> On 08/01/2012 09:20 AM, Loris Santamaria wrote:
>>> El mié, 01-08-2012 a las 10:35 -0400, Simo Sorce escribió:
>>>> On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote:
>>>>> On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacek<pspacek at redhat.com>  wrote:
>>>>>> On 07/31/2012 12:27 AM, John Dennis wrote:
>>>>>>> What is taking so long with session bookkeeping? I don't know yet. I would
>>>>>>> need more timing instrumentation. I will say when I looked at the
>>>>>>> python-krb5
>>>>>>> code (which we use to populate the ccache from the session and read back
>>>>>>> to
>>>>>>> store in the session) seemed to be remarkably inefficient. We also elected
>>>>>>> to
>>>>>>> use file based ccache rather than in-memory ccache (that means there is a
>>>>>>> bit
>>>>>>> of file-IO occurring).
>>>>>> A note regarding python-krbV:
>>>>>> I used python-krbV extensively in my thesis for KDC stress test. Python-krbV
>>>>>> can obtain several thousands of TGTs per second (even with ccache in a
>>>>>> file). AFAIK VFS calls are not done synchronously. But others parts of
>>>>>> python-krbV were left uncovered, so it can contain some surprises.
>>>>>>
>>>>>> === Wild speculation follows ===
>>>>>> 1.5 second is incredibly long time, it sounds like some kind of timeout.
>>>>>> Krb5 libs have usual timeout = 1 second per request.
>>>>>>
>>>>>> Are all KDCs in /etc/krb5.conf alive and reachable?
>>>>> In this case, as I'm referring to the extreme slowness of the Web UI,
>>>>> the KDC is on the same system (the ipa server) that is making the
>>>>> request, correct?
>>>>>
>>>>>> Is SSSD running on problematic server?
>>>>> Yes. Again, I'm guessing the problematic server is the IPA server itself.
>>>>>
>>>>>> Is proper KDC selected by SSSD KDC auto-locator plugin?
>>>>>> (See /var/lib/sss/pubconf/)
>>>>> Yes, I checked that file and it is the IP address of the IPA server on
>>>>> the same server. Perhaps should this be 127.0.0.1 instead?
>>>>>
>>>>> I also have checked the resolv.conf file, and indeed the IP points to
>>>>> the IPA server itself (same machine) as expected. Both forward and
>>>>> reverse DNS work. I'm not really sure what else could be setup
>>>>> incorrectly to cause any KDC slowness.
>>>>>
>>>>> Due to the extreme UI slowness issue, I have not created any replicas
>>>>> so this system is it. I'm not so sure I would be able to see the 1.5 s
>>>>> delay if it weren't compounded by the overall slowness of the Web UI,
>>>>> however, the KDC seems to perform well for other systems in the realm.
>>>>> I'm certainly not taxing it with a huge load, but tickets seem to be
>>>>> issued without delay.
>>>> Stephen,
>>>> another user sent me a wireshark trace for a similar performance issue.
>>>> So far I see a pause when doing the first leg of a SASL authentication.
>>>> This may well explain also your issue.
>>> Hi, I experience the same delay in SASL authentication. The number I
>>> posted on freeipa-users, show a 1-2 second delay with SASL
>>> authentication:
>>>
>>> # time ldapsearch -x uid=bdteg01662 dn
>>> # extended LDIF
>>> #
>>> # LDAPv3
>>> # base<dc=xxx,dc=gob,dc=ve>  (default) with scope subtree
>>> # filter: uid=bdteg01662
>>> # requesting: dn
>>> #
>>>
>>> # bdteg01662, users, accounts, xxx.gob.ve
>>> dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve
>>>
>>> # search result
>>> search: 2
>>> result: 0 Success
>>>
>>> # numResponses: 2
>>> # numEntries: 1
>>>
>>> real    0m0.006s
>>> user    0m0.001s
>>> sys     0m0.003s
>>>
>>> # time ldapsearch -Y GSSAPI uid=bdteg01662 dn
>>> SASL/GSSAPI authentication started
>>> SASL username: admin at XXX.GOB.VE
>>> SASL SSF: 56
>>> SASL data security layer installed.
>>> # extended LDIF
>>> #
>>> # LDAPv3
>>> # base<dc=xxx,dc=gob,dc=ve>  (default) with scope subtree
>>> # filter: uid=bdteg01662
>>> # requesting: dn
>>> #
>>>
>>> # bdteg01662, users, accounts, xxx.gob.ve
>>> dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve
>>>
>>> # search result
>>> search: 4
>>> result: 0 Success
>>>
>>> # numResponses: 2
>>> # numEntries: 1
>>>
>>> real    0m2.344s
>>> user    0m0.007s
>>> sys     0m0.005s
>> Can you post excerpts from your 389 access log showing the sequence of
>> operations for this connection, bind and search?
> Here they are:
>
> [01/Aug/2012:10:39:40 -041800] conn=33 fd=70 slot=70 connection from 172.18.32.246 to 172.18.32.246
> [01/Aug/2012:10:39:40 -041800] conn=33 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
> [01/Aug/2012:10:39:42 -041800] conn=33 op=0 RESULT err=14 tag=97 nentries=0 etime=2, SASL bind in progress

Yep, this is it - this should not be taking 2 seconds.  I'd like to see 
what internal operations are going on in this time.  Try this - follow 
the directions at http://port389.org/wiki/FAQ#Troubleshooting but for 
the access log, to turn on Heavy trace output debugging:

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-level
nsslapd-accesslog-level: 4

Then turn the access log level back to the default (256) after 
reproducing the problem.  We should then be able to see the sequence of 
internal operations triggered by the BIND dn="" method=sasl version=3 
mech=GSSAPI

> [01/Aug/2012:10:39:42 -041800] conn=33 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
> [01/Aug/2012:10:39:42 -041800] conn=33 op=1 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
> [01/Aug/2012:10:39:42 -041800] conn=33 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
> [01/Aug/2012:10:39:42 -041800] conn=33 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=admin,cn=users,cn=accounts,dc=XXXX,dc=XXXX,dc=ve"
> [01/Aug/2012:10:39:42 -041800] conn=33 op=3 SRCH base="dc=XXXX,dc=XXXX,dc=ve" scope=2 filter="(uid=bdteg01662)" attrs=ALL
> [01/Aug/2012:10:39:42 -041800] conn=33 op=3 RESULT err=0 tag=101 nentries=1 etime=0
>
>
>>>
>>>
>>>
>>>> Can you test connecting to the ldap server using ldapsearch -Y GSSAPI
>>>> (you need a kerberos ticket) and telling me if you experience any
>>>> delay ?
>>>> If you could run a bunch of searches in a loop and take a wireshark
>>>> trace that may help analyzing the timings and seeing if there is a
>>>> correlation.
>>>>
>>>> Simo.
>>>>
>>>
>>> _______________________________________________
>>> Freeipa-devel mailing list
>>> Freeipa-devel at redhat.com
>>> https://www.redhat.com/mailman/listinfo/freeipa-devel