Re: postgres processes spending most of their time in the

On Fri, 28 Dec 2001, Tom Lane wrote:

> Hmm, those look perfectly normal, except one would like to think it's
> the exception not the rule to be blocking on LWLocks. If you're seeing
> a lot of semops coming from these code paths then something unhappy is
> going on (and I would imagine that 7.1 would've been worse, since it
> would busy-wait under similar conditions).
>
> Could we get some details about your application? How many active
> backends do you have, and what are they doing? A query trace
> (postmaster log with debug_print_query on) might be helpful.

Well, let's don't get too far off track. The problem, I think, is using
SysV semaphores instead of CPU-specific test-and-set locking. Unless I
misunderstand something.....

Here's some more stacks:

#0 semop (semid=1277952, sops=0xbfffeae0, nsops=1) at
../sysdeps/unix/sysv/linux/semop.c:35
#1 0x8150424 in IpcSemaphoreLock (semId=1277952, sem=4, interruptOK=0
'\000') at ipc.c:422
#2 0x8157bfb in LWLockAcquire (lockid=WALWriteLock, mode=LW_EXCLUSIVE) at
lwlock.c:271
#3 0x8095dc2 in XLogFlush (record={xlogid = 5, xrecoff = 194128600}) at
xlog.c:1230
#4 0x814af12 in BufferReplace (bufHdr=0x40401ba8) at bufmgr.c:1061
#5 0x814a231 in BufferAlloc (reln=0x4054e240, blockNum=1395,
foundPtr=0xbfffec03 "") at bufmgr.c:424
#6 0x8149dc5 in ReadBufferInternal (reln=0x4054e240, blockNum=1395,
bufferLockHeld=0 '\000')
at bufmgr.c:184
#7 0x814a802 in ReleaseAndReadBuffer (buffer=55, relation=0x4054e240,
blockNum=1395) at bufmgr.c:694
#8 0x807a3cd in heapgettup (relation=0x4054e240, dir=1, tuple=0x82af4a4,
buffer=0x82af4bc,
snapshot=0x82afb58, nkeys=0, key=0x0) at heapam.c:369
#9 0x807aad4 in heap_getnext (scan=0x82af4a0, backw=0) at heapam.c:806
#10 0x80fad1f in SeqNext (node=0x82afa30) at nodeSeqscan.c:96
#11 0x80f27bc in ExecScan (node=0x82afa30, accessMtd=0x80fac30 <SeqNext>)
at execScan.c:95
#12 0x80fad6b in ExecSeqScan (node=0x82afa30) at nodeSeqscan.c:133
#13 0x80ef84c in ExecProcNode (node=0x82afa30, parent=0x0) at
execProcnode.c:285
#14 0x80ee0e6 in ExecutePlan (estate=0x82afad0, plan=0x82afa30,
operation=CMD_SELECT, numberTuples=0,

#0 semop (semid=1277952, sops=0xbfffead4, nsops=1) at
../sysdeps/unix/sysv/linux/semop.c:35
#1 0x81504d2 in IpcSemaphoreUnlock (semId=1277952, sem=2) at ipc.c:456
#2 0x8157fa6 in LWLockRelease (lockid=WALWriteLock) at lwlock.c:455
#3 0x8095e90 in XLogFlush (record={xlogid = 5, xrecoff = 194128600}) at
xlog.c:1242
#4 0x814af12 in BufferReplace (bufHdr=0x40401ba8) at bufmgr.c:1061
#5 0x814a231 in BufferAlloc (reln=0x4054e240, blockNum=1395,
foundPtr=0xbfffec03 "") at bufmgr.c:424
#6 0x8149dc5 in ReadBufferInternal (reln=0x4054e240, blockNum=1395,
bufferLockHeld=0 '\000')
at bufmgr.c:184
#7 0x814a802 in ReleaseAndReadBuffer (buffer=55, relation=0x4054e240,
blockNum=1395) at bufmgr.c:694
#8 0x807a3cd in heapgettup (relation=0x4054e240, dir=1, tuple=0x82af4a4,
buffer=0x82af4bc,
snapshot=0x82afb58, nkeys=0, key=0x0) at heapam.c:369
#9 0x807aad4 in heap_getnext (scan=0x82af4a0, backw=0) at heapam.c:806
#10 0x80fad1f in SeqNext (node=0x82afa30) at nodeSeqscan.c:96
#11 0x80f27bc in ExecScan (node=0x82afa30, accessMtd=0x80fac30 <SeqNext>)
at execScan.c:95
#12 0x80fad6b in ExecSeqScan (node=0x82afa30) at nodeSeqscan.c:133
#13 0x80ef84c in ExecProcNode (node=0x82afa30, parent=0x0) at
execProcnode.c:285
#14 0x80ee0e6 in ExecutePlan (estate=0x82afad0, plan=0x82afa30,
operation=CMD_SELECT, numberTuples=0,

#0 semop (semid=1277952, sops=0xbfffeb24, nsops=1) at
../sysdeps/unix/sysv/linux/semop.c:35
#1 0x81504d2 in IpcSemaphoreUnlock (semId=1277952, sem=1) at ipc.c:456
#2 0x8157fa6 in LWLockRelease (lockid=101) at lwlock.c:455
#3 0x814c05d in TerminateBufferIO (buf=0x40401ba8) at bufmgr.c:2139
#4 0x814a338 in BufferAlloc (reln=0x4054e240, blockNum=1395,
foundPtr=0xbfffec03 "") at bufmgr.c:470
#5 0x8149dc5 in ReadBufferInternal (reln=0x4054e240, blockNum=1395,
bufferLockHeld=0 '\000')
at bufmgr.c:184
#6 0x814a802 in ReleaseAndReadBuffer (buffer=55, relation=0x4054e240,
blockNum=1395) at bufmgr.c:694
#7 0x807a3cd in heapgettup (relation=0x4054e240, dir=1, tuple=0x82af4a4,
buffer=0x82af4bc,
snapshot=0x82afb58, nkeys=0, key=0x0) at heapam.c:369
#8 0x807aad4 in heap_getnext (scan=0x82af4a0, backw=0) at heapam.c:806
#9 0x80fad1f in SeqNext (node=0x82afa30) at nodeSeqscan.c:96
#10 0x80f27bc in ExecScan (node=0x82afa30, accessMtd=0x80fac30 <SeqNext>)
at execScan.c:95
#11 0x80fad6b in ExecSeqScan (node=0x82afa30) at nodeSeqscan.c:133
#12 0x80ef84c in ExecProcNode (node=0x82afa30, parent=0x0) at
execProcnode.c:285
#13 0x80ee0e6 in ExecutePlan (estate=0x82afad0, plan=0x82afa30,
operation=CMD_SELECT, numberTuples=0,

I've got 5-10 backends running, always busy. I think if Pg could keep up
my application's parallelism would increase to 15-20. All the backends
are connected to the same database, with 10 tables + indexes, and the
cycle looks like such:

begin
select
insert approx 20 rows on four tables
update 1 table
commit
goto begin

I think it's pretty basic. It used to run right quickly before I moved to
7.2beta4. My application machine saw loads of 25+, now it only sees loads
of about 3. Postgres is throttling it.

-jwb