#6656 sasl_interactive_bind_s is slow
Closed: fixed 5 years ago by rcritten. Opened 7 years ago by cheimes.

The sasl_interactive_bind_s call in Python-ldap is rather slow. It takes about 40ms per call. Out of 100 analyzed requests, 98 called sasl_interactive_bind_s and spent a total of 3.93 seconds inside the function. That's almost 2/3 of the cumulative time spent in LDAP code. result4 was called 898 with about 2ms each call and search_ext 447 times with ~1ms each call.

Here are the raw numbers from another profile run:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      299   11.234    0.038   11.236    0.038 {built-in method sasl_interactive_bind_s}
     2713    2.654    0.001    2.654    0.001 {built-in method result4}
     1354    0.645    0.000    0.645    0.000 {built-in method search_ext}

We should figure out why SASL bind is so slow. It's on second place right after SSL reads from Dogtag.


Simo pointed out that SASL bind is slow because the ticket is not cached between HTTP requests. Journal contains tons of lines like

Feb 10 15:47:17 master.ipa.example [7572]: GSSAPI client step 1
Feb 10 15:47:17 master.ipa.example [7572]: GSSAPI client step 2

and krb5kdc.log shows a TGS request for every HTTP request:

Feb 10 15:45:02 master.ipa.example krb5kdc[5667](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.154: ISSUE: authtime 1486741408, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for ldap/master.ipa.example@IPA.EXAMPLE
Feb 10 15:45:02 master.ipa.example krb5kdc[5667](info): ... CONSTRAINED-DELEGATION s4u-client=admin@IPA.EXAMPLE

The situation may improve with FreeIPA 4.5 and GSS-Proxy. Let's check again when privilege separation patch has landed.

https://github.com/freeipa/freeipa/pull/314 caused some changes in the log output. LDAP service tickets are still not retained between requests.

Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487166023, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487166023, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487165579, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for ldap/master.ipa.example@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): ... CONSTRAINED-DELEGATION s4u-client=admin@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487166023, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487166023, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5590](info): closing down fd 11
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487165579, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for ldap/master.ipa.example@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): ... CONSTRAINED-DELEGATION s4u-client=admin@IPA.EXAMPLE
Feb 15 13:40:23 master.ipa.example krb5kdc[5589](info): closing down fd 11

Further tests showed that lack of Kerberos ticket cache is not the main issue. Just sasl_interactive_bind_s in a loop takes between 25 to 40ms average per authentication. For 5k calls in a tight loop, mean and median are about 40ms. The CPU load of ns-slapd spikes to 70% to 90% on an Intel i7-4900MQ CPU with 2.80 GHz.

$ kinit admin
$ ./testsasl.py 
Loop    100
Total   2.94593 sec
Mean    0.02946 sec
Min     0.01509 sec
Median  0.03004 sec
Max     0.04850 sec
$ ./testsasl.py 
Loop    100
Total   2.31047 sec
Mean    0.02310 sec
Min     0.02008 sec
Median  0.02141 sec
Max     0.04567 sec
$ ./testsasl.py 
Loop    100
Total   3.74981 sec
Mean    0.03750 sec
Min     0.02241 sec
Median  0.03615 sec
Max     0.06138 sec
$ ./testsasl.py
Loop    5000
Total   202.73899 sec
Mean    0.04055 sec
Min     0.01603 sec
Median  0.04083 sec
Max     0.35900 sec

50 to 85% request time spent in sasl binding:

[Sun Feb 19 15:23:07.285175 2017] [wsgi:error] [pid 29521] ipa: INFO: [jsonserver_session] admin@IPA.EXAMPLE: selinuxusermap_find(u'', sizelimit=0, version=u'2.218', pkey_only=True): SUCCESS
--------------------------------------------------------------------------------
PATH: '/session/json'
         4000 function calls (3862 primitive calls) in 0.056 seconds

   Ordered by: internal time, call count
   List reduced from 383 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.048    0.048    0.048    0.048 {built-in method sasl_interactive_bind_s}
        2    0.002    0.001    0.002    0.001 {gssapi.raw.ext_cred_store.acquire_cred_from}
        3    0.001    0.000    0.001    0.000 {built-in method result4}
      477    0.000    0.000    0.000    0.000 {isinstance}
     87/3    0.000    0.000    0.001    0.000 /usr/lib64/python2.7/copy.py:145(deepcopy)
       21    0.000    0.000    0.001    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:327(_add_attr_name)
        1    0.000    0.000    0.000    0.000 {built-in method unbind_ext}
       21    0.000    0.000    0.001    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:374(_set_raw)
       87    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/copy.py:267(_keep_alive)
        2    0.000    0.000    0.000    0.000 {built-in method search_ext}
       12    0.000    0.000    0.050    0.004 /usr/lib64/python2.7/site-packages/ldap/ldapobject.py:87(_ldap_call)
      239    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
       59    0.000    0.000    0.000    0.000 /usr/lib/python2.7/site-packages/ipalib/base.py:464(__getitem__)
        1    0.000    0.000    0.004    0.004 /usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py:1983(execute)
       43    0.000    0.000    0.000    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:316(_attr_name)
       43    0.000    0.000    0.000    0.000 /usr/lib/python2.7/site-packages/ipapython/ipautil.py:568(__setitem__)
      203    0.000    0.000    0.000    0.000 {id}
       82    0.000    0.000    0.000    0.000 {getattr}
       18    0.000    0.000    0.000    0.000 /usr/lib/python2.7/site-packages/ipalib/frontend.py:492(_repr_iter)
      2/1    0.000    0.000    0.004    0.004 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:1324(find_entries)



[Sun Feb 19 15:30:35.250004 2017] [wsgi:error] [pid 29521] ipa: INFO: [jsonserver_session] admin@IPA.EXAMPLE: host_show(u'252.121.168.192.in-addr.arpa.', version=u'2.218'): NotFound
--------------------------------------------------------------------------------
PATH: '/session/json'
         4455 function calls (4282 primitive calls) in 0.042 seconds

   Ordered by: internal time, call count
   List reduced from 377 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.021    0.021    0.021    0.021 {built-in method sasl_interactive_bind_s}
        5    0.003    0.001    0.003    0.001 {built-in method result4}
        2    0.002    0.001    0.002    0.001 {gssapi.raw.ext_cred_store.acquire_cred_from}
     91/5    0.001    0.000    0.003    0.001 /usr/lib64/python2.7/copy.py:145(deepcopy)
      693    0.001    0.000    0.001    0.000 {isinstance}
       21    0.000    0.000    0.002    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:327(_add_attr_name)
       91    0.000    0.000    0.001    0.000 /usr/lib64/python2.7/copy.py:267(_keep_alive)
        4    0.000    0.000    0.000    0.000 {built-in method search_ext}
       21    0.000    0.000    0.003    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:374(_set_raw)
      235    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
       25    0.000    0.000    0.002    0.000 /usr/lib64/python2.7/copy.py:226(_deepcopy_list)
      216    0.000    0.000    0.000    0.000 {id}
       48    0.000    0.000    0.001    0.000 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:316(_attr_name)
      4/3    0.000    0.000    0.013    0.004 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:1324(find_entries)
        1    0.000    0.000    0.000    0.000 {built-in method unbind_ext}
      162    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
       43    0.000    0.000    0.000    0.000 /usr/lib/python2.7/site-packages/ipapython/ipautil.py:568(__setitem__)
       58    0.000    0.000    0.001    0.000 {method 'decode' of 'str' objects}
       18    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/site-packages/ldap/dn.py:20(escape_dn_chars)
       23    0.000    0.000    0.000    0.000 /usr/lib64/python2.7/site-packages/ldap/schema/subentry.py:206(getoid)


--------------------------------------------------------------------------------

I contacted William Brown and asked him to look into the 389-DS side of the performance issue. He was able to reproduce my benchmark results and reduced the case to low SASL performance for simple PLAIN auth, https://pagure.io/389-ds-base/issue/49136

William also pointed out that krb5_rc_io_read() inside 389-DS and SASL consumes considerable time. I'm going to contact Kerberos developers that ask for their opinion.

To clarify, the Kerberos ticket cache for LDAP tickets is still important.

After some investigation I 've come to the conclusion that in order to cache the ldap ticket we'll require some work in gssproxy that is non-trivial, so I'll defer that part for now.

With 4.4 I only see a TGS request for each JSON-RPC request, no AS request.

Feb 22 19:11:36 master.ipa.example krb5kdc[5603](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.39: ISSUE: authtime 1487790561, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for ldap/master.ipa.example@IPA.EXAMPLE
Feb 22 19:11:36 master.ipa.example krb5kdc[5603](info): ... CONSTRAINED-DELEGATION s4u-client=admin@IPA.EXAMPLE
Feb 22 19:11:36 master.ipa.example krb5kdc[5603](info): closing down fd 11

Metadata Update from @cheimes:
- Issue assigned to someone
- Issue set to the milestone: 0.0 NEEDS_TRIAGE

7 years ago

Hi,

It looks like during my work on DS I made a mistake. I have since updated the ticket for DS:

https://pagure.io/389-ds-base/issue/49136#comment-415586

It appears that SASL PLAIN and Simple binds are indistinguishable in performance.

[william@victoria]~/development/389ds% python wibrown-testsasl.py
SIMPLE BINDS
Loop    5000
Total   39.74425 sec
Mean    0.00795 sec
Min 0.00756 sec
Median  0.00783 sec
Max 0.21272 sec
SASL BINDS
Loop    5000
Total   40.92401 sec
Mean    0.00818 sec
Min 0.00781 sec
Median  0.00808 sec
Max 0.30408 sec

Sorry about this. I think this is purely a GSSAPI problem :(

Metadata Update from @cheimes:
- Custom field affects_doc reset
- Custom field blocking reset
- Custom field component reset
- Custom field keywords reset
- Custom field type reset
- Issue close_status updated to: None
- Issue set to the milestone: None (was: 0.0 NEEDS_TRIAGE)
- Issue tagged with: integration

7 years ago

Thanks a lot for looking into the issue any way! :)

Hopefully Simo's work on SPNEGO is going to help here. I might have some time in two weeks from now to profile SASL GSSAPI performance.

Metadata Update from @cheimes:
- Custom field affects_doc reset

7 years ago

The work on gssproxy side is done and will be released in v0.7, the following PR activates the feature: https://github.com/freeipa/freeipa/pull/543
We also got upstream to accept a patch to fix GSS-SPNEGO: https://github.com/cyrusimap/cyrus-sasl/pull/424 so I also opened a PR to switch to use GSS-SPNEGO for local framework connections as that reduces the bind roundtrips from 3 to 1: https://github.com/freeipa/freeipa/pull/547

master:

  • adf8aab Use GSS-SPNEGO if connecting locally

Ticket can be closed after we bump the Requires to cyrus-sasl-2.1.26-29

Metadata Update from @pvoborni:
- Issue priority set to: 2 (was: 3)
- Issue set to the milestone: FreeIPA 4.5

7 years ago

Metadata Update from @mbasti:
- Issue set to the milestone: FreeIPA 4.5.1 (was: FreeIPA 4.5)

7 years ago

Metadata Update from @pvoborni:
- Issue set to the milestone: FreeIPA 4.7 (was: FreeIPA 4.5.1)

6 years ago

Metadata Update from @rcritten:
- Issue set to the milestone: FreeIPA 4.7.1 (was: FreeIPA 4.7)

5 years ago

FreeIPA 4.7 has been released, moving to FreeIPA 4.7.1 milestone

Fedora 28 has cyrus-sasl-2.1.27-0.2rc7 so marking this as fixed.

Metadata Update from @rcritten:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

5 years ago

Login to comment on this ticket.

Metadata