OpenLDAP profiling/performance

[Ben Collins <bcollins@debian.org>]

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.

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). 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).

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().

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!

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.

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.
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
search.

For a look at the complete gprof output:

http://marcus.debian.net/~bmc/ldap/

Ben

-- 
 -----------=======-=-======-=========-----------=====------------=-=------
/  Ben Collins  --  ...on that fantastic voyage...  --  Debian GNU/Linux   \
`  bcollins@debian.org  --  bcollins@openldap.org  --  bcollins@linux.com  '
 `---=========------=======-------------=-=-----=-===-======-------=--=---'