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

To: openldap-software@OpenLDAP.org
Subject: Antwort: RE: password change takes 20 seconds
From: thomas.emde@scaleon.de
Date: Wed, 20 Feb 2002 09:36:55 +0100
Sensitivity:
Hi,

I have to explain that I am running Linux on S/390 under VM. (SuSE with Kernel
2.2.16). Funny is that
the problem does appear as described below when I define only one CPU for my
Linux. When I
give it two CPUs, it speeds very well...

I did a strace -Tf on the password change command and found out that one
specific select-syscall
takes a lot longer when using only one CPU:

The process in question is ldappasswd.

two CPUs:

snip

462   select(1024, NULL, [4], NULL, NULL) = 1 (out [4]) <0.000035>
462   getpeername(4, {sin_family=AF_INET, sin_port=htons(389),
sin_addr=inet_addr("10.11.12.13")}}, [16]) = 0 <0.000012>
462   fcntl(4, F_GETFL)                 = 0x802 (flags O_RDWR|O_NONBLOCK)
<0.000015>
462   fcntl(4, F_SETFL, O_RDWR)         = 0 <0.000014>
462   brk(0x4b6000)                     = 0x4b6000 <0.000018>
462   time(NULL)                        = 1014193187 <0.000015>
462   write(4, "01\2\1\1`,\2\1\3\4\35cn=Admin, o=myorg "..., 51) = 51 <0.000068>
462   select(1024, [4], [], NULL, NULL) = 1 (in [4]) <0.000288>
462   read(4, "0\f\2\1\1a\7\n\1\0\4\0\4\0", 16384) = 14 <0.000019>
462   time(NULL)                        = 1014193187 <0.000015>
462   time(NULL)                        = 1014193187 <0.000015>
462   write(4, "0M\2\1\2wH\200\0271.3.6.1.4.1.4203.1.11.1"..., 79) = 79
<0.000047>
462   select(1024, [4], [], NULL, NULL) = 1 (in [4]) <0.355696>
<<<<<CHECK THIS, QUITE SHORT
462   read(4, "0\f\2\1\2x\7\n\1\0\4\0\4\0", 16384) = 14 <0.000022>


snip

one CPU:

snip

5391  select(1024, NULL, [4], NULL, NULL) = 1 (out [4]) <0.000013>
5391  getpeername(4, {sin_family=AF_INET, sin_port=htons(389),
sin_addr=inet_addr("10.11.12.13")}}, [16]) = 0 <0.000007>
5391  fcntl(4, F_GETFL)                 = 0x802 (flags O_RDWR|O_NONBLOCK)
<0.000005>
5391  fcntl(4, F_SETFL, O_RDWR)         = 0 <0.000005>
5391  brk(0x421000)                     = 0x421000 <0.000008>
5391  time(NULL)                        = 1014193312 <0.000006>
5391  write(4, "01\2\1\1`,\2\1\3\4\35cn=Admin, o=myorg "..., 51) = 51 <0.000231>
5391  select(1024, [4], [], NULL, NULL) = 1 (in [4]) <0.065198>
5391  read(4, "0\f\2\1\1a\7\n\1\0\4\0\4\0", 16384) = 14 <0.000012>
5391  time(NULL)                        = 1014193312 <0.000005>
5391  time(NULL)                        = 1014193312 <0.000006>
5391  write(4, "0M\2\1\2wH\200\0271.3.6.1.4.1.4203.1.11.1"..., 79) = 79
<0.000857>
5391  select(1024, [4], [], NULL, NULL) = 1 (in [4]) <22.013631>
<<<<< VERY VERY LONG TIME....
5391  read(4, "0\f\2\1\2x\7\n\1\0\4\0\4\0", 16384) = 14 <0.000012>

snip

Any ideas?

regards,
Thomas




"Howard Chu" <hyc@highlandsun.com> on 2002-02-15 13:38:47


An:    <thomas.emde@scaleon.de>, <openldap-software@OpenLDAP.org>
Kopie:
Blindkopie:
Thema: RE: password change takes 20 seconds

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
Follow-Ups:
- RE: Antwort: RE: password change takes 20 seconds
  - From: "Howard Chu" <hyc@highlandsun.com>
Prev by Date: LDAP & PAM & Solaris 7
Next by Date: access control to subtree
Index(es):
- Chronological
- Thread