freeipa

Clone
Source Code
GIT

#5448 ipa user-add slows down as more users are added
Closed: Fixed None Opened 8 years ago by pvoborni.

Closed: Fixed
Reopen Issue

Issue:
https://www.redhat.com/archives/freeipa-users/2015-November/msg00045.html

Task:

  • identify what slows the operation down
  • find out if specific DS configuration is needed e.g. for 100000
  • fix the issue :)

If solution requires to skip some parts, e.g. adding user do default user group, propose an alternative solution.

Trying to reproduce with
- Fedora 22
- freeipa-server-4.1.4-4.fc22.x86_64
- 389-ds-base-1.3.4.5-1.fc22.x86_64

The test case is: create a freeipa server, kinit admin, loop 'ipa user-add --first=t --last=b user<range>

The measurement uses stap and get the duration of each DS plugins operation callback. Only the ten highest are displayed (AVG and MAX)

Here are partial results after adding 3000 users and 5000 users.

/tmp/output_3123_3222  (sample of 100 user-add with already 3000 existing users)
=====================
    AVG
statechange_mod_post_op      duration min 18  avg 28    max 110     count 803
statechange_add_post_op      duration min 11  avg 33    max 10060   count 1103
acl_modified             duration min 12  avg 37    max 158     count 202
sync_mod_persist_post_op     duration min 5   avg 37    max 3117    count 102
backend_bind_cb          duration min 17  avg 39    max 146     count 303
ipauuid_add_pre_op       duration min 7   avg 49    max 8932    count 1103
dna_mod_pre_op           duration min 41  avg 227   max 3527    count 703
backend_shr_betxn_post_add_cb    duration min 17  avg 228   max 30832   count 903
backend_shr_betxn_post_modify_cb duration min 58  avg 1401  max 50473   count 703
backend_search_cb        duration min 7   avg 4448  max 106282  count 10753

    MAX
retrocl_postop_add       duration min 7   avg 26    max 7067    count 903
deref_pre_entry          duration min 3   avg 5     max 7760    count 8142
automember_add_pre_op        duration min 4   avg 13    max 8124    count 1103
ipauuid_add_pre_op       duration min 7   avg 49    max 8932    count 1103
statechange_add_post_op      duration min 11  avg 33    max 10060   count 1103
sync_srch_refresh_pre_entry      duration min 3   avg 6     max 10448   count 8343
deref_pre_search         duration min 3   avg 10    max 18864   count 10753
backend_shr_betxn_post_add_cb    duration min 17  avg 228   max 30832   count 903
backend_shr_betxn_post_modify_cb duration min 58  avg 1401  max 50473   count 703
backend_search_cb        duration min 7   avg 4448  max 106282  count 10753

output_5348_5447  (sample of 100 user-add with already 5000 existing users)
================

    AVG
retrocl_postop_add       duration min 7   avg 22    max 4039    count 893
mep_mod_post_op          duration min 10  avg 25    max 3770    count 794
statechange_mod_post_op      duration min 18  avg 29    max 107     count 794
acl_modified             duration min 15  avg 40    max 227     count 198
backend_bind_cb          duration min 17  avg 46    max 476     count 300
ipauuid_add_pre_op       duration min 7   avg 50    max 6445    count 1091
dna_mod_pre_op           duration min 41  avg 387   max 3321    count 695
backend_shr_betxn_post_add_cb    duration min 18  avg 590   max 66532   count 893
backend_shr_betxn_post_modify_cb duration min 58  avg 3702  max 108879  count 695
backend_search_cb        duration min 6   avg 8224  max 228283  count 10659

    MAX
automember_add_pre_op        duration min 4   avg 11    max 5524    count 1091
backend_betxn_pre_write_cb   duration min 10  avg 18    max 5609    count 1885
memberof_postop_add          duration min 11  avg 22    max 5793    count 1091
ipauuid_add_pre_op       duration min 7   avg 50    max 6445    count 1091
deref_pre_entry          duration min 3   avg 5     max 6499    count 8074
ipamodrdn_config_check_post_op   duration min 4   avg 14    max 7163    count 1885
ipapwd_post_modadd       duration min 5   avg 15    max 8013    count 2083
backend_shr_betxn_post_add_cb    duration min 18  avg 590   max 66532   count 893
backend_shr_betxn_post_modify_cb duration min 58  avg 3702  max 108879  count 695
backend_search_cb        duration min 6   avg 8224  max 228283  count 10659

First conclusions are

Top callback directly related to the number of user are in slapi-nis:

avg/similar increase
    backend_shr_betxn_post_add_cb    (2 times 3000 vs 5000)
    backend_shr_betxn_post_modify_cb (2 times 3000 vs 5000)
    backend_search_cb        (2 times 3000 vs 5000)

Others callback that seem to be related to the number of users are:

avg similar - max increase
    backend_bind_cb          (3 times 3000 vs 5000)


avg increase - max similar
    dna_mod_pre_op           (1.5 times 3000 vs 5000)

Finally callback are likely not the "killers" are:

Is no longer a top consumer
    statechange_add_post_op
    sync_mod_persist_post_op
    deref_pre_search
    mep_mod_post_op

Is a new top consumer
    backend_betxn_pre_write_cb
    memberof_postop_add
    ipamodrdn_config_check_post_op
    ipapwd_post_modadd

avg/max similar
    statechange_mod_post_op
    acl_modified
    ipauuid_add_pre_op
    retrocl_postop_add
    deref_pre_entry
    automember_add_pre_op

After provisioning ~40000 users, the test is to add a single user
time ipa user-add --first=t --last=b tb<number>

- The layout of time spent is (total time ~7.5s)


                * DS: 42-45% (ADD+MOD+BIND+SRCH)  ~2.9s
                        - ADD:   25-26%                  ~1.8s
                        - MOD:   10-13%                  ~0.8s
                        - BIND:   3%                     ~0.2s
                        - SRCH:   3% (membership search) ~0.2s

                * others 55-58%                   ~3.6s
                        - CLI
                        - networking latency (DS detecting the op)
                        - ???



      Note:
            CLI taken with 'time'
            DS taken with etime (ms) of the req

- Focus on DS side (40000 entries), Disabling schema-compat plugin, the layout of time spent is (total time is ~2.3s)


                * DS: 21-27% (ADD+MOD+BIND+SRCH)  ~0.6
                        - ADD:   5-9%                     ~0.15s
                        - MOD:   15-16%                   ~0.40s
                        - BIND:   1%                      ~0.02s
                        - SRCH:   0.5%                    ~0.01s

                * others 72-78%                   ~1.6s
                        - CLI
                        - networking latency (DS detecting the op)
                        - ???



- So when schema-compat is enabled (duration ~7.5 sec)
    - the %age of time spent in Schema-compat plugin is
        - ADD:  90%
        - MOD:  50%
        - BIND: 90%
        - SRCH: 90%
    - It also seems to have an impact on the overall command that is slowed down

    Next:
- check if it is possible to optimize schema-compat on ADD and MOD
- check if cost of backend_search_cb, backend_shr_betxn_post_add/mod have a linear relation with the number of users.

- During user-add the ADD operation accounts for ~25% of the overall CLI.
  90% of the duration of the ADD operation is spent in the schema-compat plugins. Almost all the duration is spent doing 6 internal searches that are also expensive 
  doing direct searchs. The backtraces of the searches are copy/paste at the end of the update.

  Those searches last (from the most costly to the less):


        etime=0.393000
        etime=0.377000
        etime=0.265000
        etime=0.153000
        etime=0.135000
        etime=0.044000



- Those searches are issued by DS plugins: DNA, uniqueness
  * two first searches are from DNA plugin searching for 'Posix IDs 
- three next searches are from 'uid uniqueness' of 'uid', 'ipaUniqueID' and 'krbPrincipalName'
- The last one is issued by schema-compat itself and lookup the ipausers groups. So depending if it requests the members it may last proportionally as the number of users.

- In fact changing the configuration of the scope of DNA and uniqueness plugin accelerates ADD by 10 times

<before change>


[23/Dec/2015:18:10:13 +0100] conn=17 op=7 RESULT err=0 tag=105 nentries=0 etime=1.469000
[23/Dec/2015:18:10:22 +0100] conn=18 op=6 RESULT err=0 tag=105 nentries=0 etime=1.416000
[23/Dec/2015:18:10:30 +0100] conn=19 op=6 RESULT err=0 tag=105 nentries=0 etime=1.443000
[23/Dec/2015:18:10:38 +0100] conn=20 op=6 RESULT err=0 tag=105 nentries=0 etime=1.544000
[23/Dec/2015:18:10:47 +0100] conn=21 op=6 RESULT err=0 tag=105 nentries=0 etime=1.459000
[23/Dec/2015:18:10:56 +0100] conn=22 op=6 RESULT err=0 tag=105 nentries=0 etime=1.828000
[23/Dec/2015:18:11:05 +0100] conn=23 op=6 RESULT err=0 tag=105 nentries=0 etime=1.445000
[23/Dec/2015:18:11:14 +0100] conn=24 op=6 RESULT err=0 tag=105 nentries=0 etime=1.456000
[23/Dec/2015:18:11:23 +0100] conn=25 op=6 RESULT err=0 tag=105 nentries=0 etime=1.552000


< after changes >


[23/Dec/2015:18:14:31 +0100] conn=17 op=7 RESULT err=0 tag=105 nentries=0 etime=0.189000
[23/Dec/2015:18:14:37 +0100] conn=18 op=6 RESULT err=0 tag=105 nentries=0 etime=0.172000
[23/Dec/2015:18:14:44 +0100] conn=19 op=6 RESULT err=0 tag=105 nentries=0 etime=0.161000
[23/Dec/2015:18:14:53 +0100] conn=20 op=6 RESULT err=0 tag=105 nentries=0 etime=0.149000
[23/Dec/2015:18:15:01 +0100] conn=21 op=6 RESULT err=0 tag=105 nentries=0 etime=0.184000
[23/Dec/2015:18:15:08 +0100] conn=22 op=6 RESULT err=0 tag=105 nentries=0 etime=0.175000
[23/Dec/2015:18:15:15 +0100] conn=23 op=6 RESULT err=0 tag=105 nentries=0 etime=0.134000
[23/Dec/2015:18:15:23 +0100] conn=24 op=6 RESULT err=0 tag=105 nentries=0 etime=0.109000
[23/Dec/2015:18:15:31 +0100] conn=25 op=6 RESULT err=0 tag=105 nentries=0 etime=0.142000



- For those results the config changes are
    cn=ipaUniqueID uniqueness,cn=plugins,cn=config
        < nsslapd-pluginarg1: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
        ---
        > nsslapd-pluginarg1: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com

    cn=krbCanonicalName uniqueness,cn=plugins,cn=config
        < nsslapd-pluginarg1: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
        ---
        > nsslapd-pluginarg1: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com

    cn=krbPrincipalName uniqueness,cn=plugins,cn=config
        < nsslapd-pluginarg1: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
        ---
        > nsslapd-pluginarg1: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com

    cn=uid uniqueness,cn=plugins,cn=config
        < uniqueness-subtrees: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
        ---
        > uniqueness-subtrees: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com


    cn=Posix IDs,cn=Distributed Numeric Assignment Plugin,cn=plugins,cn=config
        < dnaScope: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
        ---
        > dnaScope: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com


Next steps
    - For uniqueness, we can duplicate entries per subtrees we want to check. 
      so the change of config should be possible
    - For DNA, the change is possibly not invalid (need to check other subtrees
              than cn=accounts, like hbac, kerberos...). It may require a change in DNA to
              support several subtrees in the configuration
- Check if it is possible to optimize the lookup of the ipausers group (from schema-compat itself)
    - Check if it is possible to optimise the MOD




THE following is the raw data of the 6 most costly searches done during ADD
================================================================================

[23/Dec/2015:15:54:23 +0100] conn=170 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(&(|(objectClass=posixAccount)(objectClass=posixGroup)(objectClass=ipaIDobject))(|(uidNumber=1677038171)(gidNumber=1677038171)))" attrs="distinguishedName"
[23/Dec/2015:15:54:23 +0100] conn=170 op=1 RESULT err=0 tag=101 nentries=2 etime=0.393000



Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50050b50, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$13 = 0x7f8d5004b5c0 "cn=Distributed Numeric Assignment Plugin,cn=plugins,cn=config"
$14 = 0x55f483a68b90 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$15 = 0x7f8d50046090 "(&(|(objectClass=posixAccount)(objectClass=posixGroup)(objectClass=ipaIDobject))(|(uidNumber=1677038171)(gidNumber=1677038171)))"
$16 = 2
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50050b50, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d50050b50, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=pb@entry=0x7f8d50050b50, callback_data=callback_data@entry=0x7f8d45fe6310, prc=prc@entry=0x7f8d74600790 <internal_plugin_result_callback>, psec=psec@entry=0x7f8d746007e0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f8d746007a0 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d746018b8 in search_internal_pb (pb=pb@entry=0x7f8d50050b50) at ldap/servers/slapd/plugin_internal_op.c:636
#7  0x00007f8d74601b13 in slapi_search_internal_pb (pb=pb@entry=0x7f8d50050b50) at ldap/servers/slapd/plugin_internal_op.c:545
#8  0x00007f8d69fe2437 in dna_first_free_value (config_entry=config_entry@entry=0x55f48bd28790, newval=newval@entry=0x7f8d45fe64a0) at ldap/servers/plugins/dna/dna.c:2258
#9  0x00007f8d69fe5782 in _dna_pre_op_add (errstr=0x7f8d45fe6460, e=0x7f8d5004db10, pb=0x7f8d45feab00) at ldap/servers/plugins/dna/dna.c:3425
#10 dna_pre_op (pb=0x7f8d45feab00, modtype=<optimized out>) at ldap/servers/plugins/dna/dna.c:3856
#13 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=450) at ldap/servers/slapd/plugin.c:438
#14 0x00007f8d67efd4fb in ldbm_back_add (pb=0x7f8d45feab00) at ldap/servers/slapd/back-ldbm/ldbm_add.c:320
#15 0x00007f8d745a2c8a in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:714
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226


================================================================================


[23/Dec/2015:15:54:23 +0100] conn=169 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(&(|(objectClass=posixAccount)(objectClass=posixGroup)(objectClass=ipaIDobject))(|(uidNumber=1677038171)(gidNumber=1677038171)))" attrs="distinguishedName"
[23/Dec/2015:15:54:23 +0100] conn=169 op=1 RESULT err=0 tag=101 nentries=2 etime=0.377000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50034e90, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$29 = 0x7f8d50002de0 "cn=Distributed Numeric Assignment Plugin,cn=plugins,cn=config"
$30 = 0x55f483a68b90 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$31 = 0x7f8d50040890 "(&(|(objectClass=posixAccount)(objectClass=posixGroup)(objectClass=ipaIDobject))(|(uidNumber=1677038171)(gidNumber=1677038171)))"
$32 = 2
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50034e90, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d50034e90, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=pb@entry=0x7f8d50034e90, callback_data=callback_data@entry=0x7f8d45fe62a0, prc=prc@entry=0x7f8d74600790 <internal_plugin_result_callback>, psec=psec@entry=0x7f8d746007e0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f8d746007a0 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d746018b8 in search_internal_pb (pb=pb@entry=0x7f8d50034e90) at ldap/servers/slapd/plugin_internal_op.c:636
#7  0x00007f8d74601b13 in slapi_search_internal_pb (pb=pb@entry=0x7f8d50034e90) at ldap/servers/slapd/plugin_internal_op.c:545
#8  0x00007f8d69fe2437 in dna_first_free_value (config_entry=config_entry@entry=0x55f48bd28790, newval=newval@entry=0x7f8d45fe6448) at ldap/servers/plugins/dna/dna.c:2258
#9  0x00007f8d69fe3dde in dna_get_next_value (next_value_ret=0x7f8d45fe6420, config_entry=0x55f48bd28790) at ldap/servers/plugins/dna/dna.c:2390
#10 dna_be_txn_pre_op (pb=0x7f8d45feab00, modtype=1) at ldap/servers/plugins/dna/dna.c:4115
#13 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=460) at ldap/servers/slapd/plugin.c:438
#14 0x00007f8d67efd20a in ldbm_back_add (pb=0x7f8d45feab00) at ldap/servers/slapd/back-ldbm/ldbm_add.c:830
#15 0x00007f8d745a2c8a in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:714
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226

================================================================================

[23/Dec/2015:15:54:22 +0100] conn=168 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(&(objectClass=posixAccount)(|(uid=tb38189)))" attrs="distinguishedName"
[23/Dec/2015:15:54:23 +0100] conn=168 op=1 RESULT err=0 tag=101 nentries=1 etime=0.265000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50046cb0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$53 = 0x7f8d50040930 "cn=uid uniqueness,cn=plugins,cn=config"
$54 = 0x55f485161e50 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$55 = 0x7f8d50002de0 "(&(objectClass=posixAccount)(|(uid=tb38189)))"
$56 = 2
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50046cb0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d50046cb0, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=pb@entry=0x7f8d50046cb0, callback_data=callback_data@entry=0x7f8d45fe6260, prc=prc@entry=0x7f8d74600790 <internal_plugin_result_callback>, psec=psec@entry=0x7f8d746007e0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f8d746007a0 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d746018b8 in search_internal_pb (pb=pb@entry=0x7f8d50046cb0) at ldap/servers/slapd/plugin_internal_op.c:636
#7  0x00007f8d74601b13 in slapi_search_internal_pb (pb=pb@entry=0x7f8d50046cb0) at ldap/servers/slapd/plugin_internal_op.c:545
#8  0x00007f8d6b4acebb in search_one_berval (baseDN=baseDN@entry=0x55f476ef4360, attrNames=attrNames@entry=0x55f482cd8010, value=0x7f8d5004d7a0, requiredObjectClass=requiredObjectClass@entry=0x55f483cfa610 "posixAccount", target=target@entry=0x7f8d50007f90, excludes=excludes@entry=0x0) at ldap/servers/plugins/uiduniq/uid.c:668
#9  0x00007f8d6b4ad2b2 in search (baseDN=0x55f476ef4360, attrNames=0x55f482cd8010, attr=0x7f8d50048a40, values=<optimized out>, requiredObjectClass=0x55f483cfa610 "posixAccount", target=0x7f8d50007f90, excludes=0x0) at ldap/servers/plugins/uiduniq/uid.c:607
#10 0x00007f8d6b4ad546 in searchAllSubtrees (subtrees=<optimized out>, exclude_subtrees=0x0, attrNames=attrNames@entry=0x55f482cd8010, attr=0x7f8d50048a40, values=values@entry=0x0, requiredObjectClass=requiredObjectClass@entry=0x55f483cfa610 "posixAccount", dn=0x7f8d50007f90, unique_in_all_subtrees=0) at ldap/servers/plugins/uiduniq/uid.c:816
#11 0x00007f8d6b4ae03a in preop_add (pb=0x7f8d45feab00) at ldap/servers/plugins/uiduniq/uid.c:1040
#14 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=460) at ldap/servers/slapd/plugin.c:438
#15 0x00007f8d67efd20a in ldbm_back_add (pb=0x7f8d45feab00) at ldap/servers/slapd/back-ldbm/ldbm_add.c:830
#16 0x00007f8d745a2c8a in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:714
#17 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226



================================================================================

[23/Dec/2015:15:54:22 +0100] conn=166 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(|(ipaUniqueID=8549a6d6-a969-11e5-bfb1-001a4a231292))" attrs="distinguishedName"
[23/Dec/2015:15:54:22 +0100] conn=166 op=1 RESULT err=0 tag=101 nentries=1 etime=0.153000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50044990, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$1 = 0x7f8d500351b0 "cn=uid uniqueness,cn=plugins,cn=config"
$2 = 0x55f483060060 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$3 = 0x7f8d500487b0 "(|(ipaUniqueID=8549a6d6-a969-11e5-bfb1-001a4a231292))"
$4 = 2
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50044990, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d50044990, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=pb@entry=0x7f8d50044990, callback_data=callback_data@entry=0x7f8d45fe64d0, prc=prc@entry=0x7f8d74600790 <internal_plugin_result_callback>, psec=psec@entry=0x7f8d746007e0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f8d746007a0 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d746018b8 in search_internal_pb (pb=pb@entry=0x7f8d50044990) at ldap/servers/slapd/plugin_internal_op.c:636
#7  0x00007f8d74601b13 in slapi_search_internal_pb (pb=pb@entry=0x7f8d50044990) at ldap/servers/slapd/plugin_internal_op.c:545
#8  0x00007f8d6b4acebb in search_one_berval (baseDN=baseDN@entry=0x55f48c6bed00, attrNames=attrNames@entry=0x55f48bf20130, value=0x7f8d500128c0, requiredObjectClass=requiredObjectClass@entry=0x0, target=target@entry=0x7f8d50035d50, excludes=excludes@entry=0x0) at ldap/servers/plugins/uiduniq/uid.c:668
#9  0x00007f8d6b4ad2b2 in search (baseDN=0x55f48c6bed00, attrNames=0x55f48bf20130, attr=0x7f8d5004d030, values=<optimized out>, requiredObjectClass=0x0, target=0x7f8d50035d50, excludes=0x0) at ldap/servers/plugins/uiduniq/uid.c:607
#10 0x00007f8d6b4ad546 in searchAllSubtrees (subtrees=<optimized out>, exclude_subtrees=0x0, attrNames=attrNames@entry=0x55f48bf20130, attr=0x7f8d5004d030, values=values@entry=0x0, requiredObjectClass=requiredObjectClass@entry=0x0, dn=0x7f8d50035d50, unique_in_all_subtrees=0) at ldap/servers/plugins/uiduniq/uid.c:816
#11 0x00007f8d6b4ae03a in preop_add (pb=0x7f8d45feab00) at ldap/servers/plugins/uiduniq/uid.c:1040
#14 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=407) at ldap/servers/slapd/plugin.c:438
#15 0x00007f8d745a2beb in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:695
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226

================================================================================
[23/Dec/2015:15:54:22 +0100] conn=167 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(|(krbPrincipalName=tb38189@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM))" attrs="distinguishedName"
[23/Dec/2015:15:54:22 +0100] conn=167 op=1 RESULT err=0 tag=101 nentries=1 etime=0.135000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50044990, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$9 = 0x7f8d500014f0 "cn=uid uniqueness,cn=plugins,cn=config"
$10 = 0x55f47445e490 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$11 = 0x7f8d500487b0 "(|(krbPrincipalName=tb38189@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM))"
$12 = 2
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d50044990, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d50044990, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=pb@entry=0x7f8d50044990, callback_data=callback_data@entry=0x7f8d45fe64d0, prc=prc@entry=0x7f8d74600790 <internal_plugin_result_callback>, psec=psec@entry=0x7f8d746007e0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f8d746007a0 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d746018b8 in search_internal_pb (pb=pb@entry=0x7f8d50044990) at ldap/servers/slapd/plugin_internal_op.c:636
#7  0x00007f8d74601b13 in slapi_search_internal_pb (pb=pb@entry=0x7f8d50044990) at ldap/servers/slapd/plugin_internal_op.c:545
#8  0x00007f8d6b4acebb in search_one_berval (baseDN=baseDN@entry=0x55f48bd68c40, attrNames=attrNames@entry=0x55f488b5d1f0, value=0x7f8d5000ceb0, requiredObjectClass=requiredObjectClass@entry=0x0, target=target@entry=0x7f8d50035d50, excludes=excludes@entry=0x0) at ldap/servers/plugins/uiduniq/uid.c:668
#9  0x00007f8d6b4ad2b2 in search (baseDN=0x55f48bd68c40, attrNames=0x55f488b5d1f0, attr=0x7f8d50014e20, values=<optimized out>, requiredObjectClass=0x0, target=0x7f8d50035d50, excludes=0x0) at ldap/servers/plugins/uiduniq/uid.c:607
#10 0x00007f8d6b4ad546 in searchAllSubtrees (subtrees=<optimized out>, exclude_subtrees=0x0, attrNames=attrNames@entry=0x55f488b5d1f0, attr=0x7f8d50014e20, values=values@entry=0x0, requiredObjectClass=requiredObjectClass@entry=0x0, dn=0x7f8d50035d50, unique_in_all_subtrees=0) at ldap/servers/plugins/uiduniq/uid.c:816
#11 0x00007f8d6b4ae03a in preop_add (pb=0x7f8d45feab00) at ldap/servers/plugins/uiduniq/uid.c:1040
#14 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=407) at ldap/servers/slapd/plugin.c:438
#15 0x00007f8d745a2beb in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:695
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226

================================================================================
    << note this one dumps ipausers group so it depends if 'member' attribute is requested >>
[23/Dec/2015:15:38:20 +0100] conn=160 op=1 SRCH base="cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=1 filter="(member=uid=tb38189,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)" attrs=ALL
[23/Dec/2015:15:38:20 +0100] conn=160 op=1 RESULT err=0 tag=101 nentries=1 etime=0.044000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d5004cac0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$57 = 0x7f8d50040380 "cn=Schema Compatibility,cn=plugins,cn=config"
$58 = 0x55f4746484d0 "cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$59 = 0x7f8d50043ab0 "(member=uid=tb38189,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)"
$60 = 1
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d5004cac0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d5004cac0, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=0x7f8d5004cac0, callback_data=<optimized out>, prc=0x0, psec=0x7f8d6614ceb0 <backend_shr_note_entry_sdn_cb>, prec=0x0) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d6614e6c7 in backend_shr_update_references_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#7  0x00007f8d6615ae9f in map_data_foreach_map () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#8  0x00007f8d6614c89b in backend_shr_update_references () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#9  0x00007f8d6614d806 in backend_shr_add_cb.part () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#10 0x00007f8d6614fe61 in backend_shr_betxn_post_add_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#13 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=560) at ldap/servers/slapd/plugin.c:438
#14 0x00007f8d67efe870 in ldbm_back_add (pb=0x7f8d45feab00) at ldap/servers/slapd/back-ldbm/ldbm_add.c:1141
#15 0x00007f8d745a2c8a in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:714
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226

- After the DNA/uniqueness changes the top consumer are


    backend_shr_betxn_post_add_cb    duration min 17  avg 27505  max 330839  count 20
    backend_search_cb        duration min 7   avg 38929  max 751778  count 255
    backend_shr_betxn_post_modify_cb duration min 51  avg 90945  max 495434  count 16



- backend_shr_betxn_post_add_cb is related to Schema Compat
  that lookups the updated group 'ipausers'. It retrieves ALL the attributes
  including 'member', so it will last longer and longer as the group 'ipausers' grows.
  It needs to be confirmed that retrieving the members is required. Likely yes as we can imagine
  that the compat group should also contain the members.
  The backtrace of the costly backend_shr_betxn_post_add_cb is



[23/Dec/2015:15:38:20 +0100] conn=160 op=1 SRCH base="cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=1 filter="(member=uid=tb38189,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)" attrs=ALL
[23/Dec/2015:15:38:20 +0100] conn=160 op=1 RESULT err=0 tag=101 nentries=1 etime=0.044000

Breakpoint 1, 0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d5004cac0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438                     rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$57 = 0x7f8d50040380 "cn=Schema Compatibility,cn=plugins,cn=config"
$58 = 0x55f4746484d0 "cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$59 = 0x7f8d50043ab0 "(member=uid=tb38189,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)"
$60 = 1
#0  0x00007f8d6614a680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7f8d5004cac0, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007f8d745f0c72 in op_shared_search (pb=pb@entry=0x7f8d5004cac0, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#5  0x00007f8d7460162e in search_internal_callback_pb (pb=0x7f8d5004cac0, callback_data=<optimized out>, prc=0x0, psec=0x7f8d6614ceb0 <backend_shr_note_entry_sdn_cb>, prec=0x0) at ldap/servers/slapd/plugin_internal_op.c:783
#6  0x00007f8d6614e6c7 in backend_shr_update_references_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#7  0x00007f8d6615ae9f in map_data_foreach_map () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#8  0x00007f8d6614c89b in backend_shr_update_references () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#9  0x00007f8d6614d806 in backend_shr_add_cb.part () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#10 0x00007f8d6614fe61 in backend_shr_betxn_post_add_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#13 plugin_call_plugins (pb=pb@entry=0x7f8d45feab00, whichfunction=whichfunction@entry=560) at ldap/servers/slapd/plugin.c:438
#14 0x00007f8d67efe870 in ldbm_back_add (pb=0x7f8d45feab00) at ldap/servers/slapd/back-ldbm/ldbm_add.c:1141
#15 0x00007f8d745a2c8a in op_shared_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:714
#16 0x00007f8d745a4008 in do_add (pb=pb@entry=0x7f8d45feab00) at ldap/servers/slapd/add.c:226




- SC call related to the MOD operation


        etime=0.238000
        etime=0.156000
        etime=0.044000
        etime=0.043000
        etime=0.043000
        etime=0.042000



- 2 first searches are done by memberof plugin 
  The first is looking for groups that contain the ADD user
  The second is looking for group membership recursively 
  (with a single 'ipausers' group it looks for groups containing 'ipausers')

- 4 last searches are the same are done by DS 
    plugin MEP             (mep_pre_op)
    plugin IPA Range-Check (ipa_range_check_pre_op)
    plugin IPA UUID        (ipauuid_pre_op)
    core pw_retry          (get_entry)

- Tuning (no tuning found for MEP) improved MOD perf by 2 times

< before tuning>


[24/Dec/2015:16:38:37 +0100] conn=19 op=10 RESULT err=0 tag=103 nentries=0 etime=0.739000
[24/Dec/2015:16:38:44 +0100] conn=20 op=10 RESULT err=0 tag=103 nentries=0 etime=0.700000
[24/Dec/2015:16:38:51 +0100] conn=21 op=10 RESULT err=0 tag=103 nentries=0 etime=0.706000
[24/Dec/2015:16:38:59 +0100] conn=22 op=10 RESULT err=0 tag=103 nentries=0 etime=0.740000
[24/Dec/2015:16:39:07 +0100] conn=23 op=10 RESULT err=0 tag=103 nentries=0 etime=0.733000
[24/Dec/2015:16:39:15 +0100] conn=24 op=10 RESULT err=0 tag=103 nentries=0 etime=0.657000
[24/Dec/2015:16:39:33 +0100] conn=25 op=10 RESULT err=0 tag=103 nentries=0 etime=0.673000
[24/Dec/2015:16:39:42 +0100] conn=26 op=10 RESULT err=0 tag=103 nentries=0 etime=0.737000



< after tuning>


[24/Dec/2015:16:44:56 +0100] conn=17 op=11 RESULT err=0 tag=103 nentries=0 etime=0.293000
[24/Dec/2015:16:45:03 +0100] conn=18 op=10 RESULT err=0 tag=103 nentries=0 etime=0.327000
[24/Dec/2015:16:45:10 +0100] conn=19 op=10 RESULT err=0 tag=103 nentries=0 etime=0.315000
[24/Dec/2015:16:45:17 +0100] conn=20 op=10 RESULT err=0 tag=103 nentries=0 etime=0.304000
[24/Dec/2015:16:45:25 +0100] conn=21 op=10 RESULT err=0 tag=103 nentries=0 etime=0.568000
[24/Dec/2015:16:45:32 +0100] conn=22 op=10 RESULT err=0 tag=103 nentries=0 etime=0.297000
[24/Dec/2015:16:45:39 +0100] conn=23 op=10 RESULT err=0 tag=103 nentries=0 etime=0.284000
[24/Dec/2015:16:45:46 +0100] conn=24 op=10 RESULT err=0 tag=103 nentries=0 etime=0.304000



- For those results the configuration changed were


IPA UUID
< ipauuidscope: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
---
> ipauuidscope: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com

IPA Range-Check
< nsslapd-basedn: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
---
> nsslapd-basedn: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com

Member of
< memberofentryscope: dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
---
> memberofentryscope: cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com





In conclusion:
    Some configuration changes can significantly reduce the cost of ADD (by 10)
and MOD (by 2).
    The overall CLI goes from 7.5s to 4.4s
    The configuration changes impact:
        - uniqueness plugin (ipaUniqueID, krbCanonicalName,krbPrincipalName and uid)
        - DNA plugin
        - memberof
        - IPA UUID
        - IPA Range-Check
        - possibly MEP plugin (scope tuning not found)

    For each of these tuning, it needs to be confirm if it is valid or how 
    it can be acheive.

THE following is the raw data of the 6 most costly searches done during MOD

================================================================================
[24/Dec/2015:13:08:26 +0100] conn=713 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(|(member=uid=tb38228,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=uid=tb38228,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com))" attrs=ALL
[24/Dec/2015:13:08:27 +0100] conn=713 op=1 RESULT err=0 tag=101 nentries=1 etime=0.238000

Breakpoint 1, 0x00007ff311de5680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7ff2dcb5b060, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$225 = 0x7ff2dcb5bf00 "cn=MemberOf Plugin,cn=plugins,cn=config"
$226 = 0x55caffbfeb40 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$227 = 0x7ff2dcb5bba0 "(|(member=uid=tb38228,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=uid=tb38228,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberH"...
$228 = 2
#0  0x00007ff311de5680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7ff2dcb5b060, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007ff32028bc72 in op_shared_search (pb=pb@entry=0x7ff2dcb5b060, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#6  0x00007ff32029cb9d in slapi_search_internal_callback_pb (pb=pb@entry=0x7ff2dcb5b060, callback_data=callback_data@entry=0x7ff2e9fe60b0, prc=prc@entry=0x0, psec=psec@entry=0x7ff3132861f0 <memberof_get_groups_callback>, prec=prec@entry=0x0) at ldap/servers/slapd/plugin_internal_op.c:564
#7  0x00007ff313286061 in memberof_call_foreach_dn (sdn=sdn@entry=0x7ff2dcb5c2b0, config=config@entry=0x7ff2e9fe6300, types=<optimized out>, callback=callback@entry=0x7ff3132861f0 <memberof_get_groups_callback>, callback_data=callback_data@entry=0x7ff2e9fe60b0, pb=0x0) at ldap/servers/plugins/memberof/memberof.c:778
#9  memberof_get_groups (member_sdn=0x7ff2dcb5c2b0, config=0x7ff2e9fe6300) at ldap/servers/plugins/memberof/memberof.c:2036
#11 0x00007ff3132874be in memberof_modop_one_replace_r (pb=pb@entry=0x7ff2e9feab00, config=config@entry=0x7ff2e9fe6300, mod_op=mod_op@entry=0, group_sdn=group_sdn@entry=0x7ff2dc02ceb0, op_this_sdn=op_this_sdn@entry=0x7ff2dc02ceb0, replace_with_sdn=replace_with_sdn@entry=0x0, op_to_sdn=0x7ff2dcb5c140, stack=0x0) at ldap/servers/plugins/memberof/memberof.c:1690
#13 memberof_modop_one (op_to_sdn=<optimized out>, op_this_sdn=0x7ff2dc02ceb0, mod_op=0, config=0x7ff2e9fe6300, pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1421
#15 0x00007ff313288ac5 in memberof_add_smod_list (smod=0x7ff2dcb619f0, group_sdn=<optimized out>, config=0x7ff2e9fe6300, pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1821
#16 memberof_postop_modify (pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1136
#19 plugin_call_plugins (pb=pb@entry=0x7ff2e9feab00, whichfunction=whichfunction@entry=561) at ldap/servers/slapd/plugin.c:438
#20 0x00007ff313bb420b in ldbm_back_modify (pb=0x7ff2e9feab00) at ldap/servers/slapd/back-ldbm/ldbm_modify.c:821
#22 0x00007ff320286647 in do_modify (pb=pb@entry=0x7ff2e9feab00) at ldap/servers/slapd/modify.c:387



================================================================================
[24/Dec/2015:13:08:27 +0100] conn=714 op=1 SRCH base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 filter="(|(member=cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com))" attrs=ALL
[24/Dec/2015:13:08:27 +0100] conn=714 op=1 RESULT err=0 tag=101 nentries=0 etime=0.156000

Breakpoint 1, 0x00007ff311de5680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7ff2dcb62830, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
438         rc = plugin_call_list(global_plugin_list[plugin_list_number], whichfunction, pb);
$229 = 0x7ff2dcb5aeb0 "cn=MemberOf Plugin,cn=plugins,cn=config"
$230 = 0x55caffbfeb40 "dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$231 = 0x7ff2dcb62700 "(|(member=cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(membe"...
$232 = 2
#0  0x00007ff311de5680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7ff2dcb62830, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007ff32028bc72 in op_shared_search (pb=pb@entry=0x7ff2dcb62830, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#6  0x00007ff32029cb9d in slapi_search_internal_callback_pb (pb=pb@entry=0x7ff2dcb62830, callback_data=callback_data@entry=0x7ff2e9fe60b0, prc=prc@entry=0x0, psec=psec@entry=0x7ff3132861f0 <memberof_get_groups_callback>, prec=prec@entry=0x0) at ldap/servers/slapd/plugin_internal_op.c:564
#7  0x00007ff313286061 in memberof_call_foreach_dn (sdn=sdn@entry=0x7ff2dd8c0240, config=0x7ff2e9fe6300, types=<optimized out>, callback=callback@entry=0x7ff3132861f0 <memberof_get_groups_callback>, callback_data=callback_data@entry=0x7ff2e9fe60b0, pb=0x0) at ldap/servers/plugins/memberof/memberof.c:778
#8  0x00007ff313286380 in memberof_get_groups_r (data=0x7ff2e9fe60b0, member_sdn=0x7ff2dd8c0240, config=<optimized out>) at ldap/servers/plugins/memberof/memberof.c:2050
#9  memberof_get_groups_callback (e=<optimized out>, callback_data=0x7ff2e9fe60b0) at ldap/servers/plugins/memberof/memberof.c:2131
#11 0x00007ff3202adc50 in send_ldap_search_entry (pb=pb@entry=0x7ff2dcb5b060, e=<optimized out>, ectrls=ectrls@entry=0x0, attrs=<optimized out>, attrsonly=<optimized out>) at ldap/servers/slapd/result.c:1053
#12 0x00007ff32028a8a3 in iterate (pb=pb@entry=0x7ff2dcb5b060, pnentries=pnentries@entry=0x7ff2e9fdfc18, pagesize=pagesize@entry=-1, pr_statp=pr_statp@entry=0x7ff2e9fdfb94, be=<optimized out>, send_result=1) at ldap/servers/slapd/opshared.c:1456
#13 0x00007ff32028aa6a in send_results_ext (pb=pb@entry=0x7ff2dcb5b060, nentries=nentries@entry=0x7ff2e9fdfc18, pagesize=-1, pr_stat=pr_stat@entry=0x7ff2e9fdfb94, send_result=1) at ldap/servers/slapd/opshared.c:1695
#14 0x00007ff32028c3d6 in op_shared_search (pb=pb@entry=0x7ff2dcb5b060, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:852
#16 0x00007ff32029cb9d in slapi_search_internal_callback_pb (pb=pb@entry=0x7ff2dcb5b060, callback_data=callback_data@entry=0x7ff2e9fe60b0, prc=prc@entry=0x0, psec=psec@entry=0x7ff3132861f0 <memberof_get_groups_callback>, prec=prec@entry=0x0) at ldap/servers/slapd/plugin_internal_op.c:564
#17 0x00007ff313286061 in memberof_call_foreach_dn (sdn=sdn@entry=0x7ff2dcb5c2b0, config=config@entry=0x7ff2e9fe6300, types=<optimized out>, callback=callback@entry=0x7ff3132861f0 <memberof_get_groups_callback>, callback_data=callback_data@entry=0x7ff2e9fe60b0, pb=0x0) at ldap/servers/plugins/memberof/memberof.c:778
#19 memberof_get_groups (member_sdn=0x7ff2dcb5c2b0, config=0x7ff2e9fe6300) at ldap/servers/plugins/memberof/memberof.c:2036
#20 memberof_fix_memberof_callback (e=0x7ff2dcb5c2b0, callback_data=callback_data@entry=0x7ff2e9fe6300) at ldap/servers/plugins/memberof/memberof.c:2876
#21 0x00007ff3132874be in memberof_modop_one_replace_r (pb=pb@entry=0x7ff2e9feab00, config=config@entry=0x7ff2e9fe6300, mod_op=mod_op@entry=0, group_sdn=group_sdn@entry=0x7ff2dc02ceb0, op_this_sdn=op_this_sdn@entry=0x7ff2dc02ceb0, replace_with_sdn=replace_with_sdn@entry=0x0, op_to_sdn=0x7ff2dcb5c140, stack=0x0) at ldap/servers/plugins/memberof/memberof.c:1690
#23 memberof_modop_one (op_to_sdn=<optimized out>, op_this_sdn=0x7ff2dc02ceb0, mod_op=0, config=0x7ff2e9fe6300, pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1421
#24 memberof_mod_smod_list (pb=pb@entry=0x7ff2e9feab00, config=config@entry=0x7ff2e9fe6300, mod=mod@entry=0, group_sdn=0x7ff2dc02ceb0, smod=smod@entry=0x7ff2dcb619f0) at ldap/servers/plugins/memberof/memberof.c:1798
#25 0x00007ff313288ac5 in memberof_add_smod_list (smod=0x7ff2dcb619f0, group_sdn=<optimized out>, config=0x7ff2e9fe6300, pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1821
#26 memberof_postop_modify (pb=0x7ff2e9feab00) at ldap/servers/plugins/memberof/memberof.c:1136
#29 plugin_call_plugins (pb=pb@entry=0x7ff2e9feab00, whichfunction=whichfunction@entry=561) at ldap/servers/slapd/plugin.c:438
#30 0x00007ff313bb420b in ldbm_back_modify (pb=0x7ff2e9feab00) at ldap/servers/slapd/back-ldbm/ldbm_modify.c:821
#31 0x00007ff320285335 in op_shared_modify (pb=pb@entry=0x7ff2e9feab00, pw_change=pw_change@entry=0, old_pw=0x0) at ldap/servers/slapd/modify.c:1054
#32 0x00007ff320286647 in do_modify (pb=pb@entry=0x7ff2e9feab00) at ldap/servers/slapd/modify.c:387


================================================================================
[24/Dec/2015:13:08:26 +0100] conn=698 op=1 SRCH base="cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=0 filter="(|(objectClass=*)(objectClass=ldapsubentry))" attrs=ALL
[24/Dec/2015:13:08:26 +0100] conn=698 op=1 RESULT err=0 tag=101 nentries=1 etime=0.044000
[24/Dec/2015:13:08:26 +0100] conn=697 op=1 RESULT err=0 tag=101 nentries=1 etime=0.043000
[24/Dec/2015:13:08:26 +0100] conn=707 op=1 RESULT err=0 tag=101 nentries=1 etime=0.043000
[24/Dec/2015:13:08:26 +0100] conn=696 op=1 RESULT err=0 tag=101 nentries=1 etime=0.042000

$202 = 0x7ff2dc04dc40 "cn=ipausers,cn=groups,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
$203 = 0x7ff3202e8d58 "(|(objectclass=*)(objectclass=ldapsubentry))"
$204 = 0
#0  0x00007ff311de5680 in backend_search_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so
#3  plugin_call_plugins (pb=pb@entry=0x7ff2dd0fb060, whichfunction=whichfunction@entry=403) at ldap/servers/slapd/plugin.c:438
#4  0x00007ff32028bc72 in op_shared_search (pb=pb@entry=0x7ff2dd0fb060, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:559
#7  0x00007ff32029cc63 in slapi_search_internal_get_entry (dn=dn@entry=0x7ff2dc02ceb0, attrs=attrs@entry=0x0, ret_entry=ret_entry@entry=0x7ff2e9fe64f8, component_identity=0x55caffa726b0) at ldap/servers/slapd/plugin_internal_op.c:919
#8  0x00007ff3134942c2 in mep_pre_op (pb=0x7ff2e9feab00, modop=4) at ldap/servers/plugins/mep/mep.c:2135
#11 plugin_call_plugins (pb=pb@entry=0x7ff2e9feab00, whichfunction=whichfunction@entry=461) at ldap/servers/slapd/plugin.c:438
#12 0x00007ff313bb341f in ldbm_back_modify (pb=0x7ff2e9feab00) at ldap/servers/slapd/back-ldbm/ldbm_modify.c:649
#14 0x00007ff320286647 in do_modify (pb=pb@entry=0x7ff2e9feab00) at ldap/servers/slapd/modify.c:387



================================================================================

Summary of tests done on

F23
freeipa-server-4.2.3-1
389-ds-base-1.3.4.5-1

After provisioning 50K users.

Initial durations

time ipa user-add --first=t --last=b tb51411 => 0m10.655s
        connection -> BIND:     etime: 3sec (kerberos) (1)
        BIND:                   etime: 1sec
        ADD:                    etime: 2.787000
        MOD:                    etime: 1.546000
        SRCH: 24 out of 25 almost immediate
               1                etime: 0.812000
                base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
                scope=2
                filter="(|(member=uid=tb51411,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=uid=tb51411,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberHost=uid=tb51411,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com))"

(1) This is the delay between the connection establishment (by 'ipa user-add) and the start of the CLI (BIND)
during this delay there are several kerberos lookup (ipa-kdb).

Test disabling Scheam compat plugin

time ipa user-add --first=t --last=b tb50333  ==> 0m1.666s
    connection -> BIND:     etime: 0sec
    BIND:           etime: 1sec
    ADD:            etime: 0.074000
    MOD:            etime: 0.494000
    SRCH: 24 out of 24 almost immediate

This tests shows that the major impact of the increasing response time is related to 'Schema Compat' plugin.

Tuning plugins to avoid schema compat scope
* uniqueness, dna and sidgen (for ADD)
* memberof (for MOD)

time ipa user-add --first=t --last=b tb51371 => 0m6.449s
    connection -> BIND:     etime: 3sec (kerberos through ldapi)
    BIND:           etime: 1sec
    ADD:            etime: 0.317000
    MOD:            etime: 0.494000 
    SRCH: 23 out of 24 almost immediate
           1 out of 24  etime: 0.264000 
           (returns the ipausers group)

Testing Schema compat fix
The fix makes backend_search_cb ignore:

  • 'internal op'(from plugins): that gives same results as preventing plugin to scope SC
  • 'local/ldapi' (from kerberos)

Note that the fix, does not trigger regression in IPA tests (http://www.freeipa.org/page/Testing)

time ipa user-add --first=t --last=b tb51413  => 0m3.530s
        connection -> BIND:     etime: 0sec (kerberos)
        BIND:                   etime: 0sec
        ADD:                    etime: 0.162000
        MOD:                    etime: 0.469000
        SRCH: 24 out of 25 almost immediate
               1                etime: 0.329000
                base="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
                scope=2
                filter="(|(member=uid=tb51413,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberUser=uid=tb51413,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com)(memberHost=uid=tb51413,cn=users,cn=accounts,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com))"

In conclusion

Avoiding Schema Compat evaluation is a key element for improving 'user-add', but likely to any request. This can be done by

The tests in https://fedorahosted.org/freeipa/ticket/5448#comment:10 (058-215) are done with the following cache settings:

<domain> entry cache: 200Mb
<ca> entry cache: 100Mb
DB_cache: 200Mb

(with 50K ipausers group is around 5Mb)

Regarding the costly SRCH. It returns the 'ipausers' group that is a big entry. But the majority of the cost is due to filter evaluation against that entry.

[09/Feb/2016:17:39:27 +0100] conn=2534 fd=67 slot=67 SSL connection from <client@> to <server@>
[09/Feb/2016:17:39:27 +0100] conn=2534 TLS1.2 128-bit AES 
[09/Feb/2016:17:39:28 +0100] conn=2534 op=1 RESULT err=14 tag=97 nentries=0 etime=0.016000, SASL bind in progress
[09/Feb/2016:17:39:29 +0100] conn=2534 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[09/Feb/2016:17:39:29 +0100] conn=2534 op=3 BIND dn="" method=sasl version=3 mech=GSSAPI
[09/Feb/2016:17:39:29 +0100] conn=2534 op=4 SRCH base="cn=ipausers,cn=groups,cn=accounts,<SUFFIX>" scope=2 filter="(objectClass=*)" attrs=ALL
[09/Feb/2016:17:39:29 +0100] conn=2534 op=3 RESULT err=0 tag=97 nentries=0 etime=0.004000 dn="uid=admin,cn=users,cn=accounts,<SUFFIX>"
[09/Feb/2016:17:39:29 +0100] conn=2534 op=2 RESULT err=14 tag=97 nentries=0 etime=0.012000, SASL bind in progress
[09/Feb/2016:17:39:29 +0100] conn=2534 op=4 RESULT err=0 tag=101 nentries=1 etime=0.121000 notes=U
[09/Feb/2016:17:39:29 +0100] conn=2534 op=5 UNBIND
[09/Feb/2016:17:39:29 +0100] conn=2534 op=5 fd=67 closed - U1
[09/Feb/2016:17:41:41 +0100] conn=2536 fd=67 slot=67 SSL connection from <client@> to <server@>
[09/Feb/2016:17:41:41 +0100] conn=2536 TLS1.2 128-bit AES
[09/Feb/2016:17:41:41 +0100] conn=2536 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[09/Feb/2016:17:41:41 +0100] conn=2536 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[09/Feb/2016:17:41:41 +0100] conn=2536 op=0 RESULT err=14 tag=97 nentries=0 etime=0.048000, SASL bind in progress
[09/Feb/2016:17:41:41 +0100] conn=2536 op=1 RESULT err=14 tag=97 nentries=0 etime=0.004000, SASL bind in progress
[09/Feb/2016:17:41:41 +0100] conn=2536 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[09/Feb/2016:17:41:41 +0100] conn=2536 op=3 SRCH base="<SUFFIX>" scope=2 filter="(|(member=uid=tb51413,cn=users,cn=accounts,<SUFFIX>)(memberUser=uid=tb51413,cn=users,cn=accounts,<SUFFIX>)(memberHost=uid=tb51413,cn=users,cn=accounts,<SUFFIX>))" attrs="distinguishedName"
[09/Feb/2016:17:41:41 +0100] conn=2536 op=2 RESULT err=0 tag=97 nentries=0 etime=0.014000 dn="uid=admin,cn=users,cn=accounts,<SUFFIX>"
[09/Feb/2016:17:41:42 +0100] conn=2536 op=3 RESULT err=0 tag=101 nentries=1 etime=0.386000
[09/Feb/2016:17:41:42 +0100] conn=2536 op=4 UNBIND 
[09/Feb/2016:17:41:42 +0100] conn=2536 op=4 fd=67 closed - U1

Linked to Bugzilla bug: https://bugzilla.redhat.com/show_bug.cgi?id=1298288 (Red Hat Enterprise Linux 7)

Closing according to Thierry: "This ticket is now fully implemented in 4.4 (slapi-nis > 0.55), it can be closed."

Metadata Update from @pvoborni:
- Issue assigned to mbasti
- Issue set to the milestone: FreeIPA 4.4
7 years ago

Login to comment on this ticket.

Metadata
None
None
None
important
None
None
None
None
defect
#5787 #5788
http://www.freeipa.org/page/V4/Performance_Improvements/Test_Plan
IPA
None
0
performance
wanted
None
None
https://bugzilla.redhat.com/show_bug.cgi?id=1298288
alich
None
http://www.freeipa.org/page/V4/Performance_Improvements
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.