Re: semtimedop instead of setitimer/semop/setitimer

Tom Lane wrote:

>AFAIK, semops are not done unless we actually have to yield the
>processor, so saving a syscall or two in that path doesn't sound like a
>big win.  I'd be more interested in asking why you're seeing long series
>of semops in the first place.
>  
>
Virtually all semops yield the processor, that part works.
I couldn't figure out what exactly causes the long series of semops. I 
tried to track it down (enable LOCK_DEBUG):
- postgres 7.3.3.
- pgbench -c 30 -t 300
- database stored on ramdisk - laptop disks are just too slow.

The long series of semops are caused by lots of processes that try to 
acquire a lock that is held exclusively by another process.
Something like
* 10 processes are waiting for a ShareLock on lock c568c. One of them 
already owns an ExclusiveLock on lock c91b4.
* everyone receives the shared lock A, does something, drops it.
* then the 9 processes try to acquire a ShareLock on lock B, and go to 
sleep.

Is there are simple way to figure out what lock c91b4 is?

Here is the log: I've added getpid() to the elog calls and I've 
overridden LOCK_DEBUG_ENABLED to write out everything always. 
Additionally, I've printed the caller address for LockAcquire

<<<<<<<<< Process 29420 acquires a lock exclusively:
LockAcquire for pid 29420 called by 0x81147d6 (XactLockTableInsert)
LockAcquire: new: 29420 lock(c91b4) tbl(1) rel(376) db(0) obj(1439) 
grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) 
type(ExclusiveLock)
LockAcquire: new: 29420 holder(c95e8) lock(c91b4) tbl(1) proc(a47b0) 
xid(1439) hold(0,0,0,0,0,0,0)=0
LockCheckConflicts: no conflict: 29420 holder(c95e8) lock(c91b4) tbl(1) 
proc(a47b0) xid(1439) hold(0,0,0,0,0,0,0)=0GrantLock: 29420 lock(c91b4) tbl(1) rel(376) db(0) obj(1439) 
grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) 
type(ExclusiveLock)
[ Snip]
<<<<< Process 29420 acquires another lock shared, goes to sleep.
LockAcquire for pid 29420 called by 0x811484a (XactLockTableWait)
LockAcquire: found: 29420 lock(c568c) tbl(1) rel(376) db(0) obj(1421) 
grantMask(80) req(0,0,0,0,2,0,1)=3 grant(0,0,0,0,0,0,1)=1 wait(2) 
type(ShareLock)
LockAcquire: new: 29420 holder(c62c0) lock(c568c) tbl(1) proc(a47b0) 
xid(1439) hold(0,0,0,0,0,0,0)=0
LockCheckConflicts: conflicting: 29420 holder(c62c0) lock(c568c) tbl(1) 
proc(a47b0) xid(1439) hold(0,0,0,0,0,0,0)=0
WaitOnLock: sleeping on lock: 29420 lock(c568c) tbl(1) rel(376) db(0) 
obj(1421) grantMask(80) req(0,0,0,0,3,0,1)=4 grant(0,0,0,0,0,0,1)=1 
wait(2) type(ShareLock)
ProcSleep from 0x8115763, pid 29420, proc 0xbf2f57b0 for 0xbf31668c, mode 5.
<<<<< omitted: several other processes sleep on the same lock.
<<<<< omitted: LockReleaseAll grants the lock to everyone that was 
sleeping on c568c
<<<< For several threads:
LOG:  ProcSleep from 0x8115763, pid 29436, proc 0xbf2f52f0 for 
0xbf31668c done.

LOG:  WaitOnLock: wakeup on lock: 29436 lock(c568c) tbl(1) rel(376) 
db(0) obj(1421) grantMask(20) req(0,0,0,0,3,0,0)=3 
grant(0,0,0,0,3,0,0)=3 wait(0) type(ShareLock)
LOG:  LockAcquire: granted: 29436 holder(c6274) lock(c568c) tbl(1) 
proc(a42f0) xid(1446) hold(0,0,0,0,1,0,0)=1
LOG:  LockAcquire: granted: 29436 lock(c568c) tbl(1) rel(376) db(0) 
obj(1421) grantMask(20) req(0,0,0,0,3,0,0)=3 grant(0,0,0,0,3,0,0)=3 
wait(0) type(ShareLock)
LOG:  LockRelease: found: 29436 lock(c568c) tbl(1) rel(376) db(0) 
obj(1421) grantMask(20) req(0,0,0,0,3,0,0)=3 grant(0,0,0,0,3,0,0)=3 
wait(0) type(ShareLock)
LOG:  LockRelease: found: 29436 holder(c6274) lock(c568c) tbl(1) 
proc(a42f0) xid(1446) hold(0,0,0,0,1,0,0)=1
LOG:  LockRelease: updated: 29436 lock(c568c) tbl(1) rel(376) db(0) 
obj(1421) grantMask(20) req(0,0,0,0,2,0,0)=2 grant(0,0,0,0,2,0,0)=2 
wait(0) type(ShareLock)
LOG:  LockRelease: updated: 29436 holder(c6274) lock(c568c) tbl(1) 
proc(a42f0) xid(1446) hold(0,0,0,0,0,0,0)=0
LOG:  LockRelease: deleting: 29436 holder(c6274) lock(c568c) tbl(1) 
proc(a42f0) xid(1446) hold(0,0,0,0,0,0,0)=0
LOG:  LockAcquire for pid 29436 called by 0x811484a. (XactLockTableWait)

LOG:  LockAcquire: found: 29436 lock(c91b4) tbl(1) rel(376) db(0) 
obj(1439) grantMask(80) req(0,0,0,0,2,0,1)=3 grant(0,0,0,0,0,0,1)=1 
wait(2) type(ShareLock)
LOG:  LockAcquire: new: 29436 holder(c6274) lock(c91b4) tbl(1) 
proc(a42f0) xid(1446) hold(0,0,0,0,0,0,0)=0
LOG:  LockCheckConflicts: conflicting: 29436 holder(c6274) lock(c91b4) 
tbl(1) proc(a42f0) xid(1446) hold(0,0,0,0,0,0,0)=0
LOG:  WaitOnLock: sleeping on lock: 29436 lock(c91b4) tbl(1) rel(376) 
db(0) obj(1439) grantMask(80) req(0,0,0,0,3,0,1)=4 
grant(0,0,0,0,0,0,1)=1 wait(2) type(ShareLock)
LOG:  ProcSleep from 0x8115763, pid 29436, proc 0xbf2f52f0 for 
0xbf31a1b4, mode 5.
<<<<<<<<<<<

Hmm. The initial exclusive lock is from XactLockTableInsert, the 
ShareLock waits are from XactLockTableWait. Everyone tries to start a 
transaction on the same entry?

I've uploaded a larger part (500 kB) of the log to 
http://www.colorfullife.com/~manfred/sql-log.gz

--   Manfred