[Freeipa-devel] slow response

[Rich Megginson]

On 08/02/2012 11:56 AM, Stephen Ingram wrote:
> On Thu, Aug 2, 2012 at 10:33 AM, Rich Megginson<rmeggins at redhat.com>  wrote:
>> On 08/02/2012 11:29 AM, Stephen Ingram wrote:
>>> On Thu, Aug 2, 2012 at 10:23 AM, Simo Sorce<simo at redhat.com>   wrote:
>>>> On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote:
>>>>> On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorce<simo at redhat.com>   wrote:
>>>>>> 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.
>>>>>>
>>>>>> 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.
>>>>> I've done this. It looks like this delay has been uncovered already
>>>>> though? I can still send you the dump privately if you think it would
>>>>> help.
>>>> I think we reproduced it, can you confirm you are also running on RHEL ?
>>>> So far it seem the only platfrom we can reproduce is RHEL 6.3
>>>
>>> Yes, I'm running RHEL 6.3. I just ran the command in the BZ and it
>>> takes 1.542s for me. What are Z-stream packages?
>>
>> They are packages delivered between minor RHEL releases e.g. between RHEL
>> 6.3 and RHEL 6.4 - the 389-ds-base package released with RHEL 6.3 was
>> 389-ds-base-1.2.10.2-15.el6 - since RHEL 6.3, we released some bugfix
>> packages, and the latest is now 389-ds-base-1.2.10.2-20.el6_3 - note the
>> "_3" at the end - this means it is a bugfix release for RHEL 6.3 -
>> "Z-stream" is just Red Hat terminology for a package released between minor
>> RHEL releases - the "Z" stands for the "Z" in the versioning scheme "X.Y.Z"
> Got it. We are using those packages now. Although this might or might
> not be the cause of the slow Web UI, the Web UI has been slow since
> the initial 6.3 release. If this 389 slowness was only introduced in
> the Z-stream 389ds, then it is likely not, or not the only, cause of
> the Web UI slowness.
The 389 slowness was not introduced in the Z-stream package (-20.el6_3) 
- the slowness is present in the RHEL 6.3.0 package (-15.el6)
>
> Steve