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.
sasl_interactive_bind_s
$ 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
attachment testsasl.py
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
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
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
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:
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
Metadata Update from @mbasti: - Issue set to the milestone: FreeIPA 4.5.1 (was: FreeIPA 4.5)
Metadata Update from @pvoborni: - Issue set to the milestone: FreeIPA 4.7 (was: FreeIPA 4.5.1)
Metadata Update from @rcritten: - Issue set to the milestone: FreeIPA 4.7.1 (was: FreeIPA 4.7)
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)
Login to comment on this ticket.