Well, you've highlighted 4 unreleased locks, a solution quite like using a sledgehammer to crack a nut but predictably efficient would be to backtrace() every lock and unlock so as to match them and to identify which locks haven't been released (but your traces show enough detail to help us focus the watch on specific db4 code).
If this can help.
After an otherwise "clean" exit of test058, the smc/db directory showed the following, despite the fact that there was no more 9196 pid on the system. Is there any facility in db4 to trace locking?
I don't think slapd's own debugging would give the level of detail that would be necessary to find a smoking gun, but if I'm just reading stuff wrong, I have the testrun directory from this.
---------- begin output ----------
Default locking region information: 138 Last allocated locker ID 0x7fffffff 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 20 Number of lock object partitions 4 Number of current locks 12 Maximum number of locks at any one time 3 Maximum number of locks in any one bucket 0 Maximum number of locks stolen by for an empty partition 0 Maximum number of locks stolen for any one partition 9 Number of current lockers 15 Maximum number of lockers at any one time 4 Number of current lock objects 8 Maximum number of lock objects at any one time 2 Maximum number of lock objects in any one bucket 0 Maximum number of objects stolen by for an empty partition 0 Maximum number of objects stolen for any one partition 1009 Total number of locks requested 1005 Total number of locks released 0 Total number of locks upgraded 46 Total number of locks downgraded 4 Lock requests not available due to conflicts, for which we waited 0 Lock requests not available due to conflicts, for which we did not wait 0 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 488KB The size of the lock region 4 The number of partition locks that required waiting (0%) 4 The maximum number of times any partition lock was waited for (0%) 0 The number of object queue operations that required waiting (0%) 1 The number of locker allocations that required waiting (0%) 0 The number of region locks that required waiting (0%) 2 Maximum hash bucket length =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock REGINFO information: Lock Region type 5 Region ID __db.005 Region name 0xfecf0000 Original region address 0xfecf0000 Region address 0xfecf00c8 Region primary address 0 Region maximum allocation 0 Region allocated Region allocations: 3006 allocations, 0 failures, 0 frees, 1 longest Allocations by power-of-two sizes: 1KB 3003 2KB 0 4KB 0 8KB 0 16KB 2 32KB 0 64KB 1 128KB 0 256KB 0 512KB 0 1024KB 0 REGION_JOIN_OK Region flags =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock region parameters: 104 Lock region region mutex [0/119 0% 11775/1] 1031 locker table size 1031 object table size 616 obj_off 63456 locker_off 0 need_dd =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock conflict matrix: 0 0 0 0 0 0 0 0 0 0 0 1 0 1 0 1 0 1 0 1 1 1 1 1 1 1 1 0 0 0 0 0 0 0 0 0 0 1 1 0 0 0 0 1 1 0 0 1 0 0 0 0 0 1 0 1 1 0 0 0 0 1 1 0 0 1 0 1 0 1 0 0 0 1 1 0 1 1 1 0 1 =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by lockers: Locker Mode Count Status ----------------- Object --------------- 85 dd= 0 locks held 1 write locks 0 pid/thread 9196/1 85 READ 1 HELD id2entry.bdb handle 0 86 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 87 dd= 0 locks held 1 write locks 0 pid/thread 9196/1 87 READ 1 HELD dn2id.bdb handle 0 88 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 89 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8a dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8000013c dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8000013d dd= 0 locks held 0 write locks 0 pid/thread 9196/1 80000145 dd= 0 locks held 2 write locks 2 pid/thread 9196/1 80000145 WRITE 1 HELD 0x39548 len: 5 data: 0000000x0100 80000145 WRITE 1 HELD id2entry.bdb page 1 =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by object: Locker Mode Count Status ----------------- Object --------------- 80000145 WRITE 1 HELD 0x39548 len: 5 data: 0000000x0100
80000145 WRITE 1 HELD id2entry.bdb page 1
85 READ 1 HELD id2entry.bdb handle0
87 READ 1 HELD dn2id.bdb handle0
Benoit Donnette wrote:
Well, you've highlighted 4 unreleased locks, a solution quite like using a sledgehammer to crack a nut but predictably efficient would be to backtrace() every lock and unlock so as to match them and to identify which locks haven't been released (but your traces show enough detail to help us focus the watch on specific db4 code).
If this can help.
After an otherwise "clean" exit of test058, the smc/db directory showed the following, despite the fact that there was no more 9196 pid on the system. Is there any facility in db4 to trace locking?
After a clean shutdown there should be no locks remaining. By definition, you're looking at an unclean shutdown.
I don't think slapd's own debugging would give the level of detail that would be necessary to find a smoking gun, but if I'm just reading stuff wrong, I have the testrun directory from this.
---------- begin output ----------
Default locking region information: 138 Last allocated locker ID 0x7fffffff 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 20 Number of lock object partitions 4 Number of current locks 12 Maximum number of locks at any one time 3 Maximum number of locks in any one bucket 0 Maximum number of locks stolen by for an empty partition 0 Maximum number of locks stolen for any one partition 9 Number of current lockers 15 Maximum number of lockers at any one time 4 Number of current lock objects 8 Maximum number of lock objects at any one time 2 Maximum number of lock objects in any one bucket 0 Maximum number of objects stolen by for an empty partition 0 Maximum number of objects stolen for any one partition 1009 Total number of locks requested 1005 Total number of locks released 0 Total number of locks upgraded 46 Total number of locks downgraded 4 Lock requests not available due to conflicts, for which we waited 0 Lock requests not available due to conflicts, for which we did not wait 0 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 488KB The size of the lock region 4 The number of partition locks that required waiting (0%) 4 The maximum number of times any partition lock was waited for (0%) 0 The number of object queue operations that required waiting (0%) 1 The number of locker allocations that required waiting (0%) 0 The number of region locks that required waiting (0%) 2 Maximum hash bucket length =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock REGINFO information: Lock Region type 5 Region ID __db.005 Region name 0xfecf0000 Original region address 0xfecf0000 Region address 0xfecf00c8 Region primary address 0 Region maximum allocation 0 Region allocated Region allocations: 3006 allocations, 0 failures, 0 frees, 1 longest Allocations by power-of-two sizes: 1KB 3003 2KB 0 4KB 0 8KB 0 16KB 2 32KB 0 64KB 1 128KB 0 256KB 0 512KB 0 1024KB 0 REGION_JOIN_OK Region flags =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock region parameters: 104 Lock region region mutex [0/119 0% 11775/1] 1031 locker table size 1031 object table size 616 obj_off 63456 locker_off 0 need_dd =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Lock conflict matrix: 0 0 0 0 0 0 0 0 0 0 0 1 0 1 0 1 0 1 0 1 1 1 1 1 1 1 1 0 0 0 0 0 0 0 0 0 0 1 1 0 0 0 0 1 1 0 0 1 0 0 0 0 0 1 0 1 1 0 0 0 0 1 1 0 0 1 0 1 0 1 0 0 0 1 1 0 1 1 1 0 1 =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by lockers: Locker Mode Count Status ----------------- Object --------------- 85 dd= 0 locks held 1 write locks 0 pid/thread 9196/1 85 READ 1 HELD id2entry.bdb handle 0 86 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 87 dd= 0 locks held 1 write locks 0 pid/thread 9196/1 87 READ 1 HELD dn2id.bdb handle 0 88 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 89 dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8a dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8000013c dd= 0 locks held 0 write locks 0 pid/thread 9196/1 8000013d dd= 0 locks held 0 write locks 0 pid/thread 9196/1 80000145 dd= 0 locks held 2 write locks 2 pid/thread 9196/1 80000145 WRITE 1 HELD 0x39548 len: 5 data: 0000000x0100 80000145 WRITE 1 HELD id2entry.bdb page 1 =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Locks grouped by object: Locker Mode Count Status ----------------- Object --------------- 80000145 WRITE 1 HELD 0x39548 len: 5 data: 0000000x0100
80000145 WRITE 1 HELD id2entry.bdb page 1
85 READ 1 HELD id2entry.bdb handle0
87 READ 1 HELD dn2id.bdb handle0
On Thu, 11 Jun 2009, Howard Chu wrote:
After a clean shutdown there should be no locks remaining. By definition, you're looking at an unclean shutdown.
By "clean" I mean: log ends with "slapd stopped." (i.e. didn't abort mid-program), and rc=0. But yes, obviously the database is unclean...
Perhaps the alternate phrasing: yes, it's unclean, why did I get a happy rc=0 in this unhappy situation?
-
Aaron Richton -
Benoit Donnette -
Howard Chu