[Date Prev][Date Next] [Chronological] [Thread] [Top]

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

To: openldap-software@OpenLDAP.org
Subject: Re: The speed of adding an entry is too slow.
From: "Jay zh" <jayzh@hotmail.com>
Date: Fri, 19 Sep 2003 10:23:05 +0800

Here is the syslog when doing ldapmodrdn. About 30 secs in adding/deleting operation(key_change). When CPU was 99%, I used top and saw that CPU state of user was almost 100%.

Sep 19 09:01:06 ldap1 slapd[1965]: connection_get(12): got connid=1 Sep 19 09:01:06 ldap1 slapd[1965]: connection_read(12): checking for input on id=1 Sep 19 09:01:06 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=35 (Resource temporarily unavailable) Sep 19 09:01:06 ldap1 slapd[1965]: do_bind Sep 19 09:01:06 ldap1 slapd[1965]: >>> dnPrettyNormal: <cn=myadmin,o=myorg> Sep 19 09:01:06 ldap1 slapd[1965]: <<< dnPrettyNormal: <cn=myadmin,o=myorg>, <cn=myadmin,o=myorg> Sep 19 09:01:06 ldap1 slapd[1965]: do_bind: version=3 dn="cn=myadmin,o=myorg" method=128 Sep 19 09:01:06 ldap1 slapd[1965]: bdb_dn2entry_rw("cn=myadmin,o=myorg") Sep 19 09:01:06 ldap1 slapd[1965]: => bdb_dn2id_matched( "cn=myadmin,o=myorg" ) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_dn2id("cn=myadmin,o=myorg"): 10 (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_id( 10 ) "cn=myadmin,o=myorg" (found) (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_return_entry_r( 10 ): returned (0) Sep 19 09:01:06 ldap1 slapd[1965]: do_bind: v3 bind: "cn=myadmin,o=myorg" to "cn=myadmin,o=myorg" Sep 19 09:01:06 ldap1 slapd[1965]: send_ldap_result: conn=1 op=0 p=3 Sep 19 09:01:06 ldap1 slapd[1965]: send_ldap_response: msgid=1 tag=97 err=0 Sep 19 09:01:06 ldap1 slapd[1965]: connection_get(12): got connid=1 Sep 19 09:01:06 ldap1 slapd[1965]: connection_read(12): checking for input on id=1 Sep 19 09:01:06 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=35 (Resource temporarily unavailable) Sep 19 09:01:06 ldap1 slapd[1965]: do_modrdn Sep 19 09:01:06 ldap1 slapd[1965]: >>> dnPrettyNormal: <cn=1:2:3:4:5:6,ou=mydevice,o=myorg > Sep 19 09:01:06 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 19 09:01:06 ldap1 slapd[1965]: >>> dnPrettyNormal: <cn=6:5:4:3:2:1> Sep 19 09:01:06 ldap1 slapd[1965]: <<< dnPrettyNormal: <cn=6:5:4:3:2:1>, <cn=6:5:4:3:2:1> Sep 19 09:01:06 ldap1 slapd[1965]: bdb_dn2entry_rw("cn=1:2:3:4:5:6,ou=mydevice,o=myorg") Sep 19 09:01:06 ldap1 slapd[1965]: => bdb_dn2id_matched( "cn=1:2:3:4:5:6,ou=mydevice,o=myorg" ) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_dn2id("cn=1:2:3:4:5:6,ou=mydevice,o=myorg"): 4653 (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_id( 4653 ) "cn=1:2:3:4:5:6,ou=mydevice,o=myorg" (found) (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_return_entry_r( 4653 ): returned (0) Sep 19 09:01:06 ldap1 slapd[1965]: ==>bdb_modrdn(cn=1:2:3:4:5:6,ou=mydevice,o=myorg,cn=6:5:4:3:2:1,NULL) Sep 19 09:01:06 ldap1 slapd[1965]: bdb_dn2entry_rw("cn=1:2:3:4:5:6,ou=mydevice,o=myorg") Sep 19 09:01:06 ldap1 slapd[1965]: => bdb_dn2id_matched( "cn=1:2:3:4:5:6,ou=mydevice,o=myorg" ) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_dn2id("cn=1:2:3:4:5:6,ou=mydevice,o=myorg"): 4653 (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: ====> bdb_cache_find_entry_id( 4653 ) "cn=1:2:3:4:5:6,ou=mydevice,o=myorg" (found) (1 tries) Sep 19 09:01:06 ldap1 slapd[1965]: => bdb_dn2id_children( cn=1:2:3:4:5:6,ou=mydevice,o=myorg ) Sep 19 09:01:07 ldap1 slapd[1965]: <= bdb_dn2id_children( cn=1:2:3:4:5:6,ou=mydevice,o=myorg ): no children (-30991) Sep 19 09:01:07 ldap1 slapd[1965]: bdb_dn2entry_rw("ou=mydevice,o=myorg") Sep 19 09:01:07 ldap1 slapd[1965]: => bdb_dn2id( "ou=mydevice,o=myorg" ) Sep 19 09:01:07 ldap1 slapd[1965]: ====> bdb_cache_find_entry_dn2id("ou=mydevice,o=myorg"): 7 (1 tries) Sep 19 09:01:07 ldap1 slapd[1965]: ====> bdb_cache_find_entry_id( 7 ) "ou=mydevice,o=myorg" (found) (1 tries) Sep 19 09:01:07 ldap1 slapd[1965]: bdb_modrdn: wr to children of entry ou=mydevice,o=myorg OK Sep 19 09:01:07 ldap1 slapd[1965]: bdb_modrdn: parent dn=ou=mydevice,o=myorg Sep 19 09:01:07 ldap1 slapd[1965]: >>> dnNormalize: <cn=6:5:4:3:2:1,ou=mydevice,o=myorg> Sep 19 09:01:07 ldap1 slapd[1965]: <<< dnNormalize: <cn=6:5:4:3:2:1,ou=mydevice,o=myorg> Sep 19 09:01:07 ldap1 slapd[1965]: bdb_modrdn: new ndn=cn=6:5:4:3:2:1,ou=mydevice,o=myorg Sep 19 09:01:07 ldap1 slapd[1965]: => bdb_dn2id( "cn=6:5:4:3:2:1,ou=mydevice,o=myorg" ) Sep 19 09:01:07 ldap1 slapd[1965]: <= bdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30991) Sep 19 09:01:07 ldap1 slapd[1965]: bdb_modrdn: new_rdn_type="cn", new_rdn_val="6:5:4:3:2:1" Sep 19 09:01:07 ldap1 slapd[1965]: => bdb_dn2id_delete( "cn=1:2:3:4:5:6,ou=mydevice,o=myorg", 0x0000122d ) Sep 19 09:01:11 ldap1 slapd[1965]: <= bdb_dn2id_delete 0 Sep 19 09:01:11 ldap1 slapd[1965]: ====> bdb_cache_delete_entry( 4653 ) Sep 19 09:01:11 ldap1 slapd[1965]: => bdb_dn2id_add( "cn=6:5:4:3:2:1,ou=mydevice,o=myorg", 0x0000122d ) Sep 19 09:01:12 ldap1 slapd[1965]: <= bdb_dn2id_add: 0 Sep 19 09:01:12 ldap1 slapd[1965]: bdb_modify_internal: 0x0000122d: cn=6:5:4:3:2:1,ou=mydevice,o=myorg Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_required entry (cn=6:5:4:3:2:1,ou=mydevice,o=myorg), objectClass "mydevice" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "objectClass" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "PolicyInfo" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "ScopeInclude" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "ConfigFlag" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "RegFlag" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "subscriber" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "username" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "userPassword" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "Status" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "ConfTemplate" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "structuralObjectClass" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "entryUUID" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "creatorsName" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "createTimestamp" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "entryCSN" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "modifiersName" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "modifyTimestamp" Sep 19 09:01:12 ldap1 slapd[1965]: oc_check_allowed type "cn" Sep 19 09:01:12 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:16 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:16 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:17 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:17 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:18 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:18 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:19 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:19 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:20 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:20 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:21 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:21 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:22 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:22 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:23 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:23 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:24 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:24 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:24 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:24 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:25 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:25 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:26 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:26 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:27 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:27 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:28 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:28 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:29 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:29 ldap1 slapd[1965]: => key_change(DELETE,122d) Sep 19 09:01:29 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:29 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:30 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:30 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:31 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:31 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:32 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:32 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:33 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:33 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:34 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:34 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:35 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:35 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:36 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:36 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:37 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:37 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:39 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:39 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:41 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:41 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:41 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:41 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:42 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:42 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:43 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:43 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:44 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:44 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:45 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:45 ldap1 slapd[1965]: => key_change(ADD,122d) Sep 19 09:01:46 ldap1 slapd[1965]: <= key_change 0 Sep 19 09:01:46 ldap1 slapd[1965]: => entry_encode(0x0000122d): cn=6:5:4:3:2:1,ou=mydevice,o=myorg Sep 19 09:01:49 ldap1 slapd[1965]: bdb_modrdn: rdn modified id=0000122d dn="cn=6:5:4:3:2:1,ou=mydevice,o=myorg" Sep 19 09:01:49 ldap1 slapd[1965]: send_ldap_result: conn=1 op=1 p=3 Sep 19 09:01:49 ldap1 slapd[1965]: send_ldap_response: msgid=2 tag=109 err=0 Sep 19 09:01:49 ldap1 slapd[1965]: ====> bdb_unlocked_cache_return_entry_r( 7 ): returned (0) Sep 19 09:01:49 ldap1 slapd[1965]: ====> bdb_unlocked_cache_return_entry_w( 4653 ): created (0) Sep 19 09:01:49 ldap1 slapd[1965]: connection_get(12): got connid=1 Sep 19 09:01:49 ldap1 slapd[1965]: connection_read(12): checking for input on id=1 Sep 19 09:01:49 ldap1 slapd[1965]: ber_get_next on fd 12 failed errno=0 (Undefined error: 0) Sep 19 09:01:49 ldap1 slapd[1965]: connection_read(12): input error=-2 id=1, closing. Sep 19 09:01:49 ldap1 slapd[1965]: connection_closing: readying conn=1 sd=12 for close Sep 19 09:01:49 ldap1 slapd[1965]: connection_close: deferring conn=1 sd=12 Sep 19 09:01:49 ldap1 slapd[1965]: do_unbind Sep 19 09:01:49 ldap1 slapd[1965]: connection_resched: attempting closing conn=1 sd=12 Sep 19 09:01:49 ldap1 slapd[1965]: connection_close: conn=1 sd=12

Here is the result of dbstat -m : I saw id2entry hit ratio : 43 %, does it mean that I need to increase cachesize in DB_CONFIG file?

259KB 752B      Total cache size.
1       Number of caches.
264KB   Pool individual cache size.
0       Requested pages mapped into the process' address space.
94M     Requested pages found in the cache (95%).
4851375 Requested pages not found in the cache.
574     Pages created in the cache.
4851370 Pages read into the cache.
180875  Pages written from the cache to the backing file.
4745550 Clean pages forced from the cache.
106346  Dirty pages forced from the cache.
0       Dirty pages written by trickle-sync thread.
189192  Current total page count.
189192  Current clean page count.
0       Current dirty page count.
37      Number of hash buckets used for page location.
104M    Total number of times hash chains searched for a page.
11      The longest hash chain searched for a page.
196M    Total number of hash buckets examined for page location.
245M    The number of hash bucket locks granted without waiting.
0       The number of hash bucket locks granted after waiting.
0       The maximum number of times any hash bucket lock was waited for.
19M     The number of region locks granted without waiting.
1       The number of region locks granted after waiting.
5041316 The number of page allocations.
227M    The number of hash buckets examined during allocations
231     The max number of hash buckets examined for an allocation
4851896 The number of pages examined during allocations
48      The max number of pages examined for an allocation
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Pool File: id2entry.bdb
16384   Page size.
0       Requested pages mapped into the process' address space.
19298   Requested pages found in the cache (43%).
25696   Requested pages not found in the cache.
5       Pages created in the cache.
25696   Pages read into the cache.
315     Pages written from the cache to the backing file.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Pool File: cn.bdb
4096    Page size.
0       Requested pages mapped into the process' address space.
20M     Requested pages found in the cache (90%).
2318077 Requested pages not found in the cache.
157     Pages created in the cache.
2318074 Pages read into the cache.
114038  Pages written from the cache to the backing file.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Pool File: objectClass.bdb
4096    Page size.
0       Requested pages mapped into the process' address space.
14M     Requested pages found in the cache (99%).
96712   Requested pages not found in the cache.
22      Pages created in the cache.
96712   Pages read into the cache.
18650   Pages written from the cache to the backing file.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Pool File: dn2id.bdb
4096    Page size.
0       Requested pages mapped into the process' address space.
43M     Requested pages found in the cache (97%).
1202520 Requested pages not found in the cache.
192     Pages created in the cache.
1202520 Pages read into the cache.
23702   Pages written from the cache to the backing file.

Here is the result of dbstat -c : Is it the main reason that results in slow updating? what parameter do I need to set? I have read this FAQ http://www.openldap.org/faq/data/cache/893.html. Only DB_TXN_NOSYNC?

2513 Last allocated locker ID. 2147M Current maximum unused locker ID. 9 Number of lock modes. 1000 Maximum number of locks possible. 1000 Maximum number of lockers possible. 1000 Maximum number of lock objects possible. 23 Number of current locks. 121 Maximum number of locks at any one time. 213 Number of current lockers. 218 Maximum number of lockers at any one time. 17 Number of current lock objects. 77 Maximum number of lock objects at any one time. 75M Total number of locks requested. 72M Total number of locks released. 2536186 Total number of lock requests failing because DB_LOCK_NOWAIT was set. 10881 Total number of locks not immediately available due to conflicts. 4 Number of deadlocks. 0 Lock timeout value. 0 Number of locks that have timed out. 0 Transaction timeout value. 0 Number of transactions that have timed out. 360KB The size of the lock region.. 0 The number of region locks granted after waiting. 139M The number of region locks granted without waiting.

Thanks for your help.

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

_________________________________________________________________ Add photos to your e-mail with MSN 8. Get 2 months FREE*. http://join.msn.com/?page=features/featuredemail

Follow-Ups:
- RE: The speed of adding an entry is too slow.
  - From: "Howard Chu" <hyc@highlandsun.com>
- Multiple bases, with one base including the others
  - From: "Douglas B. Jones" <douglas@gpc.edu>

Prev by Date: Where to get Apache Help?
Next by Date: Re: High volume ldap queries causing corruption in bdb backend.
Index(es):
- Chronological
- Thread