I found another slow path in FreeIPA. After analyzing 24 JSON RPC requests, split_tokens from python-ldap's schema tokenizer was one of the dominating function calls. Nearly 25% of the cumulative request handling time was spent in this function.
Function: https://github.com/pyldap/pyldap/blob/master/Lib/ldap/schema/tokenizer.py#L10
I'll report the problem with pyldap. Perhaps somebody has time to investigate potential speedups.
== Cumulative analysis
6960926 function calls (6658725 primitive calls) in 7.718 seconds Ordered by: internal time List reduced from 969 to 30 due to restriction <30> ncalls tottime percall cumtime percall filename:lineno(function) 295 2.019 0.007 2.019 0.007 {built-in method result4} 39376 1.716 0.000 1.770 0.000 /usr/lib64/python2.7/site-packages/ldap/schema/tokenizer.py:10(split_tokens) 24 0.684 0.029 0.684 0.029 {built-in method sasl_interactive_bind_s} 32361 0.270 0.000 0.381 0.000 /usr/lib64/python2.7/site-packages/ldap/schema/models.py:257(_set_attrs) 3559 0.207 0.000 0.461 0.000 freeipa/ipalib/parameters.py:441(__init__) 39376 0.206 0.000 0.337 0.000 /usr/lib64/python2.7/site-packages/ldap/schema/tokenizer.py:52(extract_tokens) 250226/548 0.205 0.000 1.489 0.003 freeipa/ipalib/util.py:58(json_serialize) 23 0.196 0.009 3.154 0.137 /usr/lib64/python2.7/site-packages/ldap/schema/subentry.py:81(__init__)
== Single request
127.0.0.1 - - [15/Feb/2017 22:03:42] "POST /ipa/session/json HTTP/1.1" 200 - ipa: INFO: admin@IPA.EXAMPLE: batch: host_show(u'client1.ipa.example', no_members=True): SUCCESS ipa: INFO: admin@IPA.EXAMPLE: batch: host_show(u'fileserver.ipa.example', no_members=True): SUCCESS ipa: INFO: admin@IPA.EXAMPLE: batch: host_show(u'idp.ipa.example', no_members=True): SUCCESS ipa: INFO: admin@IPA.EXAMPLE: batch: host_show(u'master.ipa.example', no_members=True): SUCCESS ipa: INFO: admin@IPA.EXAMPLE: batch: host_show(u'replica1.ipa.example', no_members=True): SUCCESS ipa: INFO: [jsonserver_session] admin@IPA.EXAMPLE: batch(({u'params': ([u'client1.ipa.example'], {u'no_members': True}), u'method': u'host_show'}, {u'params': ([u'fileserver.ipa.example'], {u'no_members': True}), u'method': u'host_show'}, {u'params': ([u'idp.ipa.example'], {u'no_members': True}), u'method': u'host_show'}, {u'params': ([u'master.ipa.example'], {u'no_members': True}), u'method': u'host_show'}, {u'params': ([u'replica1.ipa.example'], {u'no_members': True}), u'method': u'host_show'}), version=u'2.218'): SUCCESS -------------------------------------------------------------------------------- PATH: '/session/json' 388809 function calls (366460 primitive calls) in 0.602 seconds Ordered by: internal time, call count List reduced from 895 to 30 due to restriction <30> ncalls tottime percall cumtime percall filename:lineno(function) 38 0.088 0.002 0.088 0.002 {built-in method result4} 1712 0.075 0.000 0.077 0.000 /usr/lib64/python2.7/site-packages/ldap/schema/tokenizer.py:10(split_tokens) 55 0.074 0.001 0.074 0.001 {open} 56 0.040 0.001 0.040 0.001 {method 'read' of 'file' objects} 13900/295 0.035 0.000 0.122 0.000 /usr/lib/python2.7/site-packages/pkg_resources/_vendor/pyparsing.py:969(_parseNoCache) 1 0.026 0.026 0.026 0.026 {built-in method sasl_interactive_bind_s} 1 0.015 0.015 0.032 0.032 /usr/lib64/python2.7/site-packages/cryptography/hazmat/backends/openssl/backend.py:5(<module>) 9120/8530 0.015 0.000 0.027 0.000 /usr/lib/python2.7/site-packages/pkg_resources/_vendor/pyparsing.py:286(__init__) 1407 0.012 0.000 0.017 0.000 /usr/lib64/python2.7/site-packages/ldap/schema/models.py:257(_set_attrs) 45876 0.011 0.000 0.012 0.000 {isinstance}
The stats were generated with the new lite-server. I used a browser to open random pages.
$ make lite-server LITESERVER_ARGS="--enable-profile=-" $ mkdir profiles $ make lite-server LITESERVER_ARGS="--enable-profile=profiles"
pyldap issue: https://github.com/pyldap/pyldap/issues/85
So 0.077s in total or 0.0154s per command was spend in split_tokens. From the measurement it is not clear whether it changes with number of commands.
I saw that split_tokens is used in python-ldap SchemaElement. I don't know what is the IPA part which uses it. I.e. whether it is schema init, which should be cached. Or it is core part of each LDAP usage.
I haven't investigated the root cause yet. Caching might help us.
master:
Metadata Update from @cheimes: - Issue assigned to someone - Issue set to the milestone: 0.0 NEEDS_TRIAGE
Problem will be fixed in future releases of pyldap / python-pyldap.
Metadata Update from @cheimes: - Custom field affects_doc reset - Custom field component 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
Metadata Update from @pvoborni: - Custom field affects_doc reset - Custom field tester adjusted to wanted - Issue set to the milestone: FreeIPA 4.6 - Issue tagged with: tracker
Metadata Update from @tkrizek: - Issue set to the milestone: FreeIPA 4.6.1 (was: FreeIPA 4.6)
Metadata Update from @tkrizek: - Issue set to the milestone: FreeIPA 4.6.2 (was: FreeIPA 4.6.1)
This has been addressed upstream in 2.4.33.
Filed https://bugzilla.redhat.com/show_bug.cgi?id=1496470 to have python-ldap updated in rawhide to pull in fixed version.
Current version in rawhide is 2.4.25.
Metadata Update from @rcritten: - Issue assigned to rcritten (was: someone)
Metadata Update from @tdudlak: - Issue set to the milestone: FreeIPA 4.6.3 (was: FreeIPA 4.6.2)
The performance issue is fixed for Python 3 servers and as soon as Python 2 moves to python2-ldap 3.0.
Metadata Update from @cheimes: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.