[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
slapd status
I know the recent flurry of activity has not been concentrating on
optimizations, but I did some profiling again anyway, out of curiosity.
I have a profile from openldap-2.0.18 compared against HEAD, running
test008.
Here are the top 35 functions from 2.0.18, sorted in total-time order. The
first 8 or so aren't really interesting; there's some distortion in the
accounting due to thread context switches. (e.g., the time attributed to
ldap_pvt_thread_join and slapd_daemon_task shouldn't be counted since those
functions were simply alseep, waiting for other threads to execute.) I think
it's interesting that there are so many more calls to ber_memfree than there
are to ber_memalloc and ber_memcalloc, and that the CPU time in free exceeds
alloc time. This also shows the large amount of time consumed in slap_bv2ad,
before AD caching.
| local | total | | |
| sec. | % | sec. | % | calls |t. sec/call| name
|-----------|-----|-----------|-----|----------|-----------|--------
| 0.017297| 0.0| 108.376677| 47.5| 1| 108.376677| main
| 0.000023| 0.0| 107.701938| 47.2| 1| 107.701938| slapd_daemon
| 107.700027| 47.2| 107.700087| 47.2| 1| 107.700087|
ldap_pvt_thread_join
| 35.064995| 15.4| 107.699870| 47.2| 1| 107.699870|
slapd_daemon_task
| 0.188650| 0.1| 100.476001| 44.0| 32| 3.139875|
ldap_int_thread_pool_wrapper
| 0.166231| 0.1| 70.804410| 31.0| 3890| 0.018202| connection_read
| 10.442645| 4.6| 64.240616| 28.2| 201067| 0.000319|
ldap_pvt_thread_mutex_unlock
| 0.152334| 0.1| 59.782786| 26.2| 3890| 0.015368|
connection_operation
| 0.366054| 0.2| 55.234430| 24.2| 3756| 0.014706| do_search
| 0.143595| 0.1| 52.564212| 23.0| 7780| 0.006756|
connection_input
| 0.109134| 0.0| 49.768480| 21.8| 3890| 0.012794|
connection_op_activate
| 0.194403| 0.1| 49.225566| 21.6| 3890| 0.012654|
ldap_pvt_thread_pool_submit
| 0.365914| 0.2| 49.217304| 21.6| 3751| 0.013121|
ldbm_back_search
| 0.381472| 0.2| 28.594541| 12.5| 3774| 0.007577|
send_search_entry
| 0.433298| 0.2| 21.529389| 9.4| 38750| 0.000556| ad_inlist
| 1.293476| 0.6| 19.485776| 8.5| 59777| 0.000326| slap_bv2ad
| 0.287965| 0.1| 18.479510| 8.1| 56021| 0.000330| slap_str2ad
| 0.124919| 0.1| 17.555499| 7.7| 7771| 0.002259| id2entry_rw
| 0.059441| 0.0| 17.418416| 7.6| 4052| 0.004299| dn2entry_rw
| 0.697351| 0.3| 16.918865| 7.4| 7771| 0.002177|
cache_find_entry_id
| 0.025107| 0.0| 16.779071| 7.4| 3890| 0.004313|
connection_return
| 0.006606| 0.0| 12.757796| 5.6| 100| 0.127578| index_entry
| 0.008455| 0.0| 12.745006| 5.6| 1800| 0.007081| index_values
| 0.011671| 0.0| 12.736551| 5.6| 2200| 0.005789| index_at_values
| 0.030673| 0.0| 12.665209| 5.6| 300| 0.042217| indexer
| 0.012218| 0.0| 11.387326| 5.0| 50| 0.227747| do_add
| 9.707098| 4.3| 10.272923| 4.5| 538919| 0.000019| ber_memfree
| 0.004422| 0.0| 10.172225| 4.5| 50| 0.203444| ldbm_back_add
| 0.343970| 0.2| 10.082737| 4.4| 6200| 0.001626| key_change
| 0.003244| 0.0| 9.688353| 4.2| 50| 0.193767| do_delete
| 0.003658| 0.0| 9.638108| 4.2| 50| 0.192762|
ldbm_back_delete
| 9.030552| 4.0| 9.501368| 4.2| 431958| 0.000022| ber_memalloc
| 1.201225| 0.5| 9.406598| 4.1| 59791| 0.000157| str2charray
| 1.739556| 0.8| 8.568663| 3.8| 347987| 0.000025| ch_free
| 5.681539| 2.5| 7.836224| 3.4| 292882| 0.000027| lutil_debug
Here's a run from HEAD a couple hours ago. Still the same alloc/free
relationship. dnNormalize is significant. (No surprise.)
| local | total | | |
| sec. | % | sec. | % | calls |t. sec/call| name
|-----------|-----|-----------|-----|----------|-----------|--------
| 0.001169| 0.0| 108.696970| 46.8| 1| 108.696970| main
| 0.000033| 0.0| 108.005594| 46.5| 1| 108.005594| slapd_daemon
| 108.003553| 46.5| 108.003569| 46.5| 1| 108.003569|
ldap_pvt_thread_join
| 51.816480| 22.3| 108.003343| 46.5| 1| 108.003343|
slapd_daemon_task
| 0.227214| 0.1| 101.207711| 43.6| 32| 3.162741|
ldap_int_thread_pool_wrapper
| 0.153404| 0.1| 57.436523| 24.7| 3893| 0.014754|
connection_operation
| 0.127003| 0.1| 54.654469| 23.5| 3893| 0.014039| connection_read
| 0.248813| 0.1| 53.633504| 23.1| 3756| 0.014279| do_search
| 1.805142| 0.8| 53.616542| 23.1| 277434| 0.000193|
ldap_pvt_thread_mutex_unlock
| 0.127591| 0.1| 47.703808| 20.5| 7786| 0.006127|
connection_input
| 0.079418| 0.0| 46.309505| 19.9| 3893| 0.011896|
connection_op_activate
| 0.081874| 0.0| 45.882203| 19.8| 3893| 0.011786|
ldap_pvt_thread_pool_submit
| 0.313033| 0.1| 27.760086| 12.0| 3751| 0.007401|
ldbm_back_search
| 0.069267| 0.0| 15.838987| 6.8| 3896| 0.004065| dnNormalize
| 0.012975| 0.0| 13.643051| 5.9| 51| 0.267511| do_add
| 0.006557| 0.0| 12.722912| 5.5| 100| 0.127229| index_entry
| 0.010236| 0.0| 12.716355| 5.5| 2200| 0.005780| index_values
| 0.012952| 0.0| 12.706119| 5.5| 2600| 0.004887| index_at_values
| 0.338766| 0.1| 12.525700| 5.4| 3774| 0.003319|
send_search_entry
| 0.032659| 0.0| 12.424287| 5.4| 400| 0.031061| indexer
| 0.047074| 0.0| 12.218372| 5.3| 7823| 0.001562| id2entry_rw
| 0.035655| 0.0| 12.095720| 5.2| 4055| 0.002983| dn2entry_rw
| 0.098567| 0.0| 11.796167| 5.1| 3947| 0.002989| dnPretty
| 0.779263| 0.3| 11.718171| 5.0| 7823| 0.001498|
cache_find_entry_id
| 10.164800| 4.4| 11.661466| 5.0| 541074| 0.000022| ber_memfree
| 0.003551| 0.0| 10.982328| 4.7| 51| 0.215340| ldbm_back_add
| 0.116053| 0.0| 10.705489| 4.6| 6700| 0.001598| key_change
| 9.234413| 4.0| 9.764194| 4.2| 461718| 0.000021| ber_memalloc
| 0.558349| 0.2| 9.221386| 4.0| 7801| 0.001182| LDAPDN_rewrite
| 0.095821| 0.0| 8.729018| 3.8| 3875| 0.002253|
send_ldap_response
| 0.260564| 0.1| 8.373850| 3.6| 7801| 0.001073| ldap_str2dn
| 0.003167| 0.0| 8.199338| 3.5| 50| 0.163987| do_delete
| 0.002686| 0.0| 7.694227| 3.3| 50| 0.153885|
ldbm_back_delete
| 1.206717| 0.5| 7.618008| 3.3| 144819| 0.000053| ber_bvfree
| 0.198840| 0.1| 7.193820| 3.1| 7649| 0.000940| send_ldap_ber
Here's a list for the HEAD as of this moment. Some time was saved by
combining dnPretty and dnNormalize. Things are definitely improving.
| local | total | | |
| sec. | % | sec. | % | calls |t. sec/call| name
|-----------|-----|-----------|-----|----------|-----------|--------
| 0.036873| 0.0| 99.007631| 47.3| 1| 99.007631| main
| 0.000034| 0.0| 98.274370| 46.9| 1| 98.274370| slapd_daemon
| 98.272346| 46.9| 98.272362| 46.9| 1| 98.272362|
ldap_pvt_thread_join
| 49.637276| 23.7| 98.272134| 46.9| 1| 98.272134|
slapd_daemon_task
| 0.184838| 0.1| 92.077065| 43.9| 32| 2.877408|
ldap_int_thread_pool_wrapper
| 0.151866| 0.1| 52.655989| 25.1| 3893| 0.013526|
connection_operation
| 0.228904| 0.1| 47.518041| 22.7| 3756| 0.012651| do_search
| 0.125935| 0.1| 47.435577| 22.6| 3893| 0.012185| connection_read
| 1.279431| 0.6| 44.948097| 21.5| 184750| 0.000243|
ldap_pvt_thread_mutex_unlock
| 0.138973| 0.1| 41.033219| 19.6| 7786| 0.005270|
connection_input
| 0.079800| 0.0| 39.629930| 18.9| 3893| 0.010180|
connection_op_activate
| 0.082389| 0.0| 39.206324| 18.7| 3893| 0.010071|
ldap_pvt_thread_pool_submit
| 0.315536| 0.2| 27.437959| 13.1| 3751| 0.007315|
ldbm_back_search
| 0.085559| 0.0| 18.782408| 9.0| 3896| 0.004821| dnPrettyNormal
| 0.331496| 0.2| 10.530825| 5.0| 3774| 0.002790|
send_search_entry
| 0.003066| 0.0| 8.591198| 4.1| 50| 0.171824| do_delete
| 7.973529| 3.8| 8.457931| 4.0| 420619| 0.000020| ber_memfree
| 0.002676| 0.0| 8.229445| 3.9| 50| 0.164589|
ldbm_back_delete
| 0.519576| 0.2| 7.785081| 3.7| 7801| 0.000998| LDAPDN_rewrite
| 0.006436| 0.0| 7.435870| 3.5| 100| 0.074359| index_entry
| 0.010159| 0.0| 7.429434| 3.5| 2200| 0.003377| index_values
| 0.012990| 0.0| 7.419275| 3.5| 2600| 0.002854| index_at_values
| 0.031327| 0.0| 7.367522| 3.5| 400| 0.018419| indexer
| 6.861593| 3.3| 7.012911| 3.3| 341263| 0.000021| ber_memalloc
| 0.048508| 0.0| 6.864157| 3.3| 7823| 0.000877| id2entry_rw
| 0.710833| 0.3| 6.600628| 3.2| 7823| 0.000844|
cache_find_entry_id
| 0.012031| 0.0| 6.358876| 3.0| 51| 0.124684| do_add
| 0.035662| 0.0| 6.126889| 2.9| 4055| 0.001511| dn2entry_rw
| 0.096403| 0.0| 6.119267| 2.9| 3875| 0.001579|
send_ldap_response
| 0.051191| 0.0| 5.924024| 2.8| 3893| 0.001522|
connection_return
| 1.534294| 0.7| 5.769935| 2.8| 45583| 0.000127|
ldap_pvt_thread_yield
| 0.909559| 0.4| 5.688351| 2.7| 109973| 0.000052| ber_bvfree
| 0.197196| 0.1| 5.526555| 2.6| 7649| 0.000723| send_ldap_ber
| 2.993693| 1.4| 5.416075| 2.6| 183045| 0.000030| avl_find
| 0.138970| 0.1| 5.401716| 2.6| 6700| 0.000806| key_change
| 0.459481| 0.2| 5.177702| 2.5| 48250| 0.000107| ad_inlist
-- Howard Chu
Chief Architect, Symas Corp. Director, Highland Sun
http://www.symas.com http://highlandsun.com/hyc
Symas: Premier OpenSource Development and Support