[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: OpenLDAP profiling/performance

At 05:01 PM 1/3/01 -0500, Ben Collins wrote:
>I've been working with a 6000 entry user database. For awhile I was
>using OpenLDAP 1.2.11, which was working great, but to take advantage of
>some of the more advanced ACL's I switched the production box to using
>OpenLDAP 2.0.7. Big mistake.

While 2.0's ACLs are "more advanced", they are also "more expensive"
(even for a set of ACLs using only 1.2 features).

>Searches for things like "uid=foo" were taking about 30 seconds (this on
>a machine with 128megs of ram and a 450Mhz PIII, dedicated to just this
>LDAP server).

Sound like you don't have an equality index on uid.

>Note, this is running under Linux, kernel 2.2.x (not that
>it matters). Also note that the openldap 1.2.11 and 2.0.7 setup were
>pretty much identical. Both of them had indexes for these attrbiutes (in
>fact, almost all of the attributes were indexed).

you have, I assume, in both:

index uid eq

(note that 'default' has different semantics in 2.0)

>I then compiled two binaries, one is 1.2.11 and the other is 2.0.7,
>using -pg (profiling). The results were a little disturbing. Here's a
>look at 2.0.7, with indexes for a single search in the 6000 entry db with
>this filter "uid=bcollins":
>                     (# of times called)
>  0.00      0.04     0.00  1830352     0.00     0.00  ch_free
>  0.00      0.04     0.00  1286279     0.00     0.00  attr_index_name_cmp
>  0.00      0.04     0.00  1241312     0.00     0.00  ch_malloc
>                           ^^^^^^^
>Note how many times these functions are called. This is mainly from
>str2entry(), which is itself called by id2entry_rw(), and that is called
>by ldbm_back_search(). Now, ldbm_back_search() is called only once in
>this scenario, while id2entry_rw() and thus str2entry(), are called
>11124 times by ldbm_back_search().

This implies you don't have an equality index on uid.
(I note that 11124 str2entry calls seems odd give a 6000 entry

>Now, let's look at the highest called functions in the 1.2.11 profile:
>  0.00      0.00     0.00     3091     0.00     0.00  ldap_pvt_thread_mutex_init
>  0.00      0.00     0.00     2397     0.00     0.00  ch_strdup
>  0.00      0.00     0.00     1188     0.00     0.00  strtok_quote
>  0.00      0.00     0.00     1030     0.00     0.00  ldap_pvt_thread_cond_init
>                              ^^^^
>Quit a bit of difference. Also, the number of times that str2entry() and
>id2entry() are called is down to a measly 2 each!

indexing in action.

>One more point, I tried both of these with and without indexing. The
>1.2.11 without indexing is comparable to that of 2.0.7 (with or
>without). OpenLDAP 2.0.7 without indexing was the same as with
>(performance wise), however the profile looks slightly different, so
>something is being done differently. I suspect the index isn't being
>used though, atleast not optimally. I also tried the head branch, and
>got the same results.

I suspect the difference is that you have some index defined
for uid but not an equality index... and hence the difference
in behavior.  Or the code could be broke...

>Kurt, any ideas on why this is happening? There looks like a lot of
>indirection has been added since openldap 1.2.x. A lot of chasing
>a single function call, iterates down 4 other consecutive functions.

The fun of attribute type subtyping....

>Also, the debugging functions are getting a high count. Now they might
>not being doing much, but the overhead in jumping from one function to
>another and then back, surely is causing some performance drop. I'm
>probably back to square one from before when I planned on rewriting the
>debug code. FYI, lutil_debug() was called 323237 times just for this

That's a separate issue.

>For a look at the complete gprof output:
> -----------=======-=-======-=========-----------=====------------=-=------
>/  Ben Collins  --  ...on that fantastic voyage...  --  Debian GNU/Linux   \
>`  bcollins@debian.org  --  bcollins@openldap.org  --  bcollins@linux.com  '
> `---=========------=======-------------=-=-----=-===-======-------=--=---'