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)=0
GrantLock: 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