[SSSD] slow logins via ssh

Stephen Gallagher sgallagh at redhat.com
Fri Sep 23 11:34:42 UTC 2011


On Fri, 2011-09-23 at 12:20 +1000, GOLLSCHEWSKY, Tim wrote:
> Hi Dmitri, thanks for your response.
> 
> >> The bit I don't understand is:  It does this even when I have "Enumerate" set to False.  Isn't Enumerate = False supposed to stop it from downloading all the group memberships?
> >>
> >> http://docs.redhat.com/docs/en-US/Red_Hat_Enterprise_Linux/6/html/Deployment_Guide/chap-SSSD_User_Guide-Configuring_Domains.html
> >>
> >> Note I'm using an "ldap_filter" on just one group to control access to the box.  So really for the initial login process it only needs to see the users that exist in one group.  The only time I would expect it to look at other groups is when somebody types the "groups" command for example or does an "ls" in a directory.
> >>
> >
> >This is not how it works. It does the resolution of the user and all his
> >membership once user logs in. We do it once at the login as we do not
> >know what  applications and user would do. You know that you never call
> >"groups" and want to offload the performance hit to it but we do not.
> >This is why we can't have partial information. There were some
> >performance issue like that that we noticed and tried to address
> >recently. What version are you running and on what OS? Some of the
> >recent 1.6 fixes might help.
> 
> I'm running RHEL6:
> 
> $ rpm -q sssd
> sssd-1.5.1-34.el6_1.3.x86_64
> 
> >Also you might extend the cache timeouts significantly but then the
> >changes made centrally would also be propagated with significant latency.
> >I also wonder if winbind would be faster... Have you ever tried winbind?
> 
> Not for many years, but if this is preferable for large organisations
> I could give it a shot.
> 
> >It will be interesting to compare its performance and sssd in your setup
> >as we are bringing it as a back end to sssd soon.
> >
> >If you can provide sanitized logs and info about how your data is
> >structured (how many groups, nesting, etc) we would be able to see if
> >this problem is something we already know about or something different.
> 
> At this point in time we have 145 groups in the "ldap_group_search_base", although this
> is growing all the time.  Each group has about 10-200 members.
> 
> So it doesn't sound like a lot, but it takes around 30 seconds to enumerate all this information
> at login time.
> 
> Here's an example of the sanitised debug logs while it's doing the enumeration (heavily grep -v'd)
> 
>   ...
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=oggap,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [oggap]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=oggap,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [oggap] is not a direct member of any groups
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=rmbad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=rmbad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [rmbad]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=rmbad,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [rmbad] is not a direct member of any groups
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=iswad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=iswad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [iswad]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=iswad,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [iswad] is not a direct member of any groups
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Saving incomplete group [voirp] to the sysdb
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=voirp,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
>   (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=voirp,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
>   ...


This isn't enough information to say where the latency is occurring. Is
the 30s passing while it's still iterating through "Looking up parent
groups for group", or are you seeing it happen while the SSSD is saving
the results to the cache? I'm guessing that the problem is likely
happening during the latter. We're doing a lot of work right now for
1.6.2 with improving the cache performance, but I'd like to try and
track this down to make sure our current enhancement plans will aid you.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20110923/1cdc00ff/attachment.sig>


More information about the sssd-devel mailing list