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

To: <thomas.emde@scaleon.de>, <openldap-software@OpenLDAP.org>
Subject: RE: Antwort: RE: password change takes 20 seconds
From: "Howard Chu" <hyc@highlandsun.com>
Date: Wed, 20 Feb 2002 02:06:09 -0800
Importance: Normal
In-reply-to: <OF4D67BF1D.833F613B-ONC1256B66.002A3AF0@bayer-ag.com>
The client's response time is entirely dependent on the server.
Perhaps an strace on the server in both single-CPU and dual-CPU modes
would show something interesting.

I have no idea how Linux was ported to VM, and how closely integrated
it is with the Supervisor. Since adding a second CPU fixes the problem,
it implies a scheduling problem in either the Linux kernel or its
interface to VM. Still the slapd logs you sent just show very very slow
database operations. Perhaps your VM partition just doesn't have enough
I/O resources allocated to it.

Try running "top" on the server while it's executing this operation, and
see how much CPU time is spent in user mode or system mode. I would guess
that the majority is in system mode, and you're just stuck waiting for
the underlying system to service your I/Os. Another thing to try is to
add "dbnosync" to your slapd.conf and see if it runs any faster. If so,
the problem is definitely in the underlying I/O.

  -- 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: Wednesday, February 20, 2002 12:37 AM
> To: openldap-software@OpenLDAP.org
> Subject: Antwort: RE: password change takes 20 seconds
>
>
>
> 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
>
>
>
>
References:
- Antwort: RE: password change takes 20 seconds
  - From: thomas.emde@scaleon.de
Prev by Date: replication question; start_tls
Next by Date: Antwort: RE: Antwort: RE: password change takes 20 seconds
Index(es):
- Chronological
- Thread