[Date Prev][Date Next] [Chronological] [Thread] [Top]
RE: password change takes 20 seconds

To: <thomas.emde@scaleon.de>, <openldap-software@OpenLDAP.org>
Subject: RE: password change takes 20 seconds
From: "Howard Chu" <hyc@highlandsun.com>
Date: Fri, 15 Feb 2002 04:38:47 -0800
Importance: Normal
In-reply-to: <OF99352DAB.EA173EB1-ONC1256B61.00345D5D@bayer-ag.com>
What kind of machine are you running on, and how busy is it? Those are
some ridiculously long times to perform those index updates. As you can
see from this debug log, in the released code, whenever you modify an
entry all of its index entries are completely rewritten, regardless of
whether they were affected by the modification. The new code has been
fixed to leave the index alone for modifications that don't affect
indexed attributes. That fix would eliminate all of the key_change()
operations you see in this example. Still, there may be something badly
configured on your server or it just may be too overloaded to run these
database operations at a reasonable pace.

  -- Howard Chu
  Chief Architect, Symas Corp.       Director, Highland Sun
  http://www.symas.com               http://highlandsun.com/hyc
  Symas: Premier OpenSource Development and Support 

> -----Original Message-----
> From: owner-openldap-software@OpenLDAP.org
> [mailto:owner-openldap-software@OpenLDAP.org]On Behalf Of
> thomas.emde@scaleon.de
> Sent: Friday, February 15, 2002 1:40 AM
> To: openldap-software@OpenLDAP.org
> Subject: password change takes 20 seconds
> 
> 
> Hello,
> 
> I am using openldap server 2.0.21 and have a little database with one
> organization unit and one test user.
> I can login to my system as this test user and now try to change 
> his password by
> using ldappasswd. Actually
> it works but it takes about 20 (!!!) seconds to perform this 
> action. Here is a
> snippet from the messages file
> which shows a lot of changes in the ldbm database which take a 
> long long time.
> Can anyone tell what is happening
> there and why?
> 
> snip
> 
> Feb 15 10:28:50 linuxhost slapd[909]: => index_entry_del( 2, "uid=mark6,
> o=myorg, c=D" )
> Feb 15 10:28:50 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/objectClass.dbb", 7, 600 )
> Feb 15 10:28:50 linuxhost slapd[909]: <= ldbm_cache_open (cache 3)
> Feb 15 10:28:50 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:51 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:51 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:51 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:51 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:51 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:51 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:52 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:52 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/uid.dbb", 7, 600 )
> Feb 15 10:28:52 linuxhost slapd[909]: <= ldbm_cache_open (cache 4)
> Feb 15 10:28:52 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:52 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:52 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:52 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:52 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:53 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:53 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:53 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:53 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:53 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:53 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:54 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:54 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:54 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:54 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:54 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:54 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:55 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:55 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:55 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:55 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/cn.dbb", 7, 600 )
> Feb 15 10:28:55 linuxhost slapd[909]: <= ldbm_cache_open (cache 5)
> Feb 15 10:28:55 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:55 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:55 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:56 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:56 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:56 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:56 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:56 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:56 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:57 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:57 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:57 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:57 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:57 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:57 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:57 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:57 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:58 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:58 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:58 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:58 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:58 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:58 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:59 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:59 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:59 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:59 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:28:59 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:28:59 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:00 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:00 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:00 linuxhost slapd[909]: <= key_change -1
> Feb 15 10:29:00 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:00 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:00 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:01 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:01 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:01 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:01 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:01 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:01 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:02 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:02 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:02 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:02 linuxhost slapd[909]: => key_change(DELETE,2)
> Feb 15 10:29:02 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:02 linuxhost slapd[909]: <= index_entry_del( 2, "uid=mark6,
> o=myorg, c=D" ) success
> Feb 15 10:29:02 linuxhost slapd[909]: => index_entry_add( 2, "uid=mark6,
> o=myorg, c=D" )
> Feb 15 10:29:02 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/objectClass.dbb", 7, 600 )
> Feb 15 10:29:02 linuxhost slapd[909]: <= ldbm_cache_open (cache 3)
> Feb 15 10:29:02 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:02 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:02 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:03 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:03 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:03 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:03 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:03 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:03 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/uid.dbb", 7, 600 )
> Feb 15 10:29:03 linuxhost slapd[909]: <= ldbm_cache_open (cache 4)
> Feb 15 10:29:03 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:03 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:03 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:04 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:04 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:04 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:04 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:04 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:04 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:04 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:04 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:04 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:04 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:05 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:05 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:05 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:05 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:05 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:05 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:06 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:06 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:06 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:06 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/cn.dbb", 7, 600 )
> Feb 15 10:29:06 linuxhost slapd[909]: <= ldbm_cache_open (cache 5)
> Feb 15 10:29:06 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:06 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:06 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:06 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:06 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:07 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:07 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:07 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:07 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:07 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:07 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:07 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:07 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:08 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:08 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:08 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:08 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:08 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:08 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:08 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:08 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:09 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:09 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:09 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:09 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:09 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:09 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:09 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:09 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:10 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:10 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:10 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:10 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:10 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:10 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:10 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:10 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:11 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:11 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:11 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:11 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:11 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:11 linuxhost slapd[909]: => key_change(ADD,2)
> Feb 15 10:29:11 linuxhost slapd[909]: <= key_change 0
> Feb 15 10:29:12 linuxhost slapd[909]: <= index_entry_add( 2, "uid=mark6,
> o=myorg, c=D" ) success
> Feb 15 10:29:12 linuxhost slapd[909]: => id2entry_add( 2, 
> "uid=mark6, o=myorg,
> c=D" )
> Feb 15 10:29:12 linuxhost slapd[909]: => ldbm_cache_open
> ( "/var/lib/ldap/id2entry.dbb", 7, 600 )
> Feb 15 10:29:12 linuxhost slapd[909]: <= ldbm_cache_open (cache 1)
> 
> snip
> 
> best regards,
> Thomas
References:
- password change takes 20 seconds
  - From: thomas.emde@scaleon.de
Prev by Date: Re: Win95 ldap api pb
Next by Date: slurpd problem
Index(es):
- Chronological
- Thread