Re: The speed of adding an entry is too slow.

["Jay zh" <jayzh@hotmail.com>]

Dear :

Here is the log, 19 secs. A lot of key_change msgs. What's the meaning? My 
original copy of  DB_CONFIG file is empty. Need to add some parameters?

Thanks for your help.

Sep 16 15:27:49 ldap1 slapd[1965]: connection_get(12): got connid=0
Sep 16 15:27:49 ldap1 slapd[1965]: connection_read(12): checking for input 
on id=0
Sep 16 15:27:49 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=35 
(Resource temporarily unavailable)
Sep 16 15:27:49 ldap1 slapd[1965]: do_bind
Sep 16 15:27:49 ldap1 slapd[1965]: >>> dnPrettyNormal: <cn=myadmin,o=myorg>
Sep 16 15:27:49 ldap1 slapd[1965]: <<< dnPrettyNormal: <cn=myadmin,o=myorg>, 
<cn=myadmin,o=myorg>
Sep 16 15:27:49 ldap1 slapd[1965]: do_bind: version=3 
dn="cn=myadmin,o=myorg" method=128
Sep 16 15:27:49 ldap1 slapd[1965]: bdb_dn2entry_rw("cn=myadmin,o=myorg")
Sep 16 15:27:49 ldap1 slapd[1965]: => bdb_dn2id_matched( 
"cn=myadmin,o=myorg" )
Sep 16 15:27:49 ldap1 slapd[1965]: <= bdb_dn2id_matched: id=0x0000000a: 
entry cn=myadmin,o=myorg
Sep 16 15:27:49 ldap1 slapd[1965]: entry_decode: "cn=myadmin,o=myorg"
Sep 16 15:27:49 ldap1 slapd[1965]: <= entry_decode(cn=myadmin,o=myorg)
Sep 16 15:27:49 ldap1 slapd[1965]: ====> bdb_cache_return_entry_r( 10 ): 
created (0)
Sep 16 15:27:49 ldap1 slapd[1965]: do_bind: v3 bind: "cn=myadmin,o=myorg" to 
"cn=myadmin,o=myorg"
Sep 16 15:27:49 ldap1 slapd[1965]: send_ldap_result: conn=0 op=0 p=3
Sep 16 15:27:49 ldap1 slapd[1965]: send_ldap_response: msgid=1 tag=97 err=0
Sep 16 15:27:49 ldap1 slapd[1965]: connection_get(12): got connid=0
Sep 16 15:27:49 ldap1 slapd[1965]: connection_read(12): checking for input 
on id=0
Sep 16 15:27:49 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=35 
(Resource temporarily unavailable)
Sep 16 15:27:49 ldap1 slapd[1965]: do_add
Sep 16 15:27:49 ldap1 slapd[1965]: >>> dnPrettyNormal: 
<cn=1:2:3:4:5:6,ou=mydevice,o=myorg>
Sep 16 15:27:49 ldap1 slapd[1965]: <<< dnPrettyNormal: 
<cn=1:2:3:4:5:6,ou=mydevice,o=myorg>, <cn=1:2:3:4:5:6,ou=mydevice,o=myorg>
Sep 16 15:27:49 ldap1 slapd[1965]: 
bdb_dn2entry_rw("cn=1:2:3:4:5:6,ou=mydevice,o=myorg")
Sep 16 15:27:49 ldap1 slapd[1965]: => bdb_dn2id_matched( 
"cn=1:2:3:4:5:6,ou=mydevice,o=myorg" )
Sep 16 15:27:49 ldap1 slapd[1965]: <= bdb_dn2id_matched: id=0x00000007: 
matched ou=mydevice,o=myorg
Sep 16 15:27:49 ldap1 slapd[1965]: entry_decode: "ou=mydevice,o=myorg"
Sep 16 15:27:49 ldap1 slapd[1965]: <= entry_decode(ou=mydevice,o=myorg)
Sep 16 15:27:49 ldap1 slapd[1965]: bdb_referrals: op=104 
target="cn=1:2:3:4:5:6,ou=mydevice,o=myorg" matched="ou=mydevice,o=myorg"
Sep 16 15:27:49 ldap1 slapd[1965]: ====> bdb_cache_return_entry_r( 7 ): 
created (0)
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_required entry 
(cn=1:2:3:4:5:6,ou=mydevice,o=myorg), objectClass "mydevice"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "cn"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "objectClass"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "PolicyInfo"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "ScopeInfo"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "ConfigFlag"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "RegFlag"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "subscriber"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "username"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "userPassword"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "Status"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type 
"structuralObjectClass"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "entryUUID"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "creatorsName"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "createTimestamp"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "entryCSN"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "modifiersName"
Sep 16 15:27:49 ldap1 slapd[1965]: oc_check_allowed type "modifyTimestamp"
Sep 16 15:27:49 ldap1 slapd[1965]: bdb_dn2entry_rw("ou=mydevice,o=myorg")
Sep 16 15:27:49 ldap1 slapd[1965]: => bdb_dn2id_matched( 
"ou=mydevice,o=myorg" )
Sep 16 15:27:49 ldap1 slapd[1965]: ====> 
bdb_cache_find_entry_dn2id("ou=mydevice,o=myorg"): 7 (1 tries)
Sep 16 15:27:49 ldap1 slapd[1965]: ====> bdb_cache_find_entry_id( 7 ) 
"ou=mydevice,o=myorg" (found) (1 tries)
Sep 16 15:27:49 ldap1 slapd[1965]: ====> bdb_unlocked_cache_return_entry_r( 
7 ): returned (0)
Sep 16 15:27:49 ldap1 slapd[1965]: => bdb_dn2id_add( 
"cn=1:2:3:4:5:6,ou=mydevice,o=myorg", 0x0000122d )
Sep 16 15:27:49 ldap1 slapd[1965]: <= bdb_dn2id_add: 0
Sep 16 15:27:49 ldap1 slapd[1965]: => entry_encode(0x0000122d): 
cn=1:2:3:4:5:6,ou=mydevice,o=myorg
Sep 16 15:27:49 ldap1 slapd[1965]: => index_entry_add( 4653, 
"cn=1:2:3:4:5:6,ou=mydevice,o=myorg" )
Sep 16 15:27:50 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:54 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:54 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:55 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:55 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:55 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:55 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:55 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:55 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:55 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:55 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:55 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:55 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:56 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:56 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:56 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:56 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:56 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:56 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:57 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:57 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:58 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:58 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:27:59 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:27:59 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:01 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:01 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:02 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:02 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:03 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:03 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:03 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:05 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:06 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:06 ldap1 slapd[1965]: => key_change(ADD,122d)
Sep 16 15:28:08 ldap1 slapd[1965]: <= key_change 0
Sep 16 15:28:08 ldap1 slapd[1965]: <= index_entry_add( 4653, 
"cn=1:2:3:4:5:6,ou=mydevice,o=myorg" ) success
Sep 16 15:28:08 ldap1 slapd[1965]: bdb_add: added id=0000122d 
dn="cn=1:2:3:4:5:6,ou=mydevice,o=myorg"
Sep 16 15:28:08 ldap1 slapd[1965]: send_ldap_result: conn=0 op=1 p=3
Sep 16 15:28:08 ldap1 slapd[1965]: send_ldap_response: msgid=2 tag=105 err=0
Sep 16 15:28:08 ldap1 slapd[1965]: ====> bdb_unlocked_cache_return_entry_w( 
4653 ): created (0)
Sep 16 15:28:08 ldap1 slapd[1965]: connection_get(12): got connid=0
Sep 16 15:28:08 ldap1 slapd[1965]: connection_read(12): checking for input 
on id=0
Sep 16 15:28:08 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=0 
(Undefined error: 0)
Sep 16 15:28:08 ldap1 slapd[1965]: connection_read(12): input error=-2 id=0, 
closing.
Sep 16 15:28:08 ldap1 slapd[1965]: connection_closing: readying conn=0 sd=12 
for close
Sep 16 15:28:08 ldap1 slapd[1965]: connection_close: deferring conn=0 sd=12
Sep 16 15:28:08 ldap1 slapd[1965]: do_unbind
Sep 16 15:28:08 ldap1 slapd[1965]: connection_resched: attempting closing 
conn=0 sd=12
Sep 16 15:28:08 ldap1 slapd[1965]: connection_close: conn=0 sd=12

> It happened to me that slapd used 99% of CPU with no response ... it was 
> before 2.1.22 and mostly (I presume) because I used a DB_CONFIG file that 
> reserved 300Mbyte (set_cachesize) on my 256 Mbyte machine ! :-(, don't know 
> if it's your case ?
>
>
> Dieter Kluenter wrote:
> > Hi,
> >
> > "Jay zh" <jayzh@hotmail.com> writes:
> >
> >
> > > Dear :
> > >
> > > OpenLDAP version is 2.1.22
> > > Berkeley DB version is 4.1.25 with patch 1
> > >
> > > When I use ldapadd to add an entry, it takes 1 min to complete this
> > > operation. Before completing this operation, CPU load is increasing up
> > > to 99%. And the syslog has a lot of "deferring operation" msgs. It
> > > seems to be the lock problem. What should I do to resolve this problem
> > > ?
> >
> >
> > For me, it takes 0.180 sec to add one entry and 3 min. to add 10,000
> > entries.
> >
> > Set 'loglevel 0' in slapd.conf and create in your openldap-data
> > directory a file DB_CONFIG with following contents:
> > add_flags DB_TXN_NOSYNC
> >
> > -Dieter
>
>
> --
> Jehan Procaccia, Ingenieur Systemes & Reseaux
> Institut National des Telecommunications, Tel : +33 (0) 160764436
> MCI,Moyens Communs Informatiques, Mail: Jehan.Procaccia@int-evry.fr
> 9 rue Charles Fourier 91011 Evry France, Fax : +33 (0) 160764321

_________________________________________________________________
Protect your PC - get McAfee.com VirusScan Online 
http://clinic.mcafee.com/clinic/ibuy/campaign.asp?cid=3963