Re: sblock state on FreeBSD 6.1

Just experienced a server that was spending over 50% of CPU time in the
system, apparently dealing with postmasters that were in the sblock
state. Looking at the FreeBSD source, this indicates that the process is
waiting for a lock on a socket. During this time the machine was doing
nearly 200k context switches a second.

At the same time, the server was also producing 'statistics buffer is
full' errors.

Has anyone seen this before? I suspect that the stats buffer errors are
a symptom and not the cause of the problem, but unfortunately I wasn't
able to get a stack trace to verify that theory.

The machine is a dual Opteron 250 with 8G of memory, running 8.1.3.
While this was going on there were between 10 and 250 backends running
at once, based on vmstat.

Any ideas what areas of the code could be locking a socket?
Theoretically it shouldn't be the stats collector, and the site is using
pgpool as a connection pool, so this shouldn't be due to trying to
connect to backends at a furious rate.
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

"Jim C. Nasby" <jnasby(at)pervasive(dot)com> writes:
> Just experienced a server that was spending over 50% of CPU time in the
> system, apparently dealing with postmasters that were in the sblock
> state. Looking at the FreeBSD source, this indicates that the process is
> waiting for a lock on a socket. During this time the machine was doing
> nearly 200k context switches a second.

Which operations require such a lock? If plain read/write needs the
lock then heavy contention is hardly surprising.

> Any ideas what areas of the code could be locking a socket?
> Theoretically it shouldn't be the stats collector, and the site is using
> pgpool as a connection pool, so this shouldn't be due to trying to
> connect to backends at a furious rate.

Actually, the stats socket seems like a really good bet to me, since all
the backends will be interested in the same socket. The
client-to-backend sockets are only touched by two processes each, so
don't seem like big contention sources.

regards, tom lane

On Tue, May 02, 2006 at 11:06:59PM -0400, Tom Lane wrote:
> "Jim C. Nasby" <jnasby(at)pervasive(dot)com> writes:
> > Just experienced a server that was spending over 50% of CPU time in the
> > system, apparently dealing with postmasters that were in the sblock
> > state. Looking at the FreeBSD source, this indicates that the process is
> > waiting for a lock on a socket. During this time the machine was doing
> > nearly 200k context switches a second.
>
> Which operations require such a lock? If plain read/write needs the
> lock then heavy contention is hardly surprising.

From what little I've been able to decypher of the FBSD kernel source,
it appears that socket creation and destruction requires the lock, as
well as (at least) writing to it, but in the latter case it depends on
some flags/options.

> > Any ideas what areas of the code could be locking a socket?
> > Theoretically it shouldn't be the stats collector, and the site is using
> > pgpool as a connection pool, so this shouldn't be due to trying to
> > connect to backends at a furious rate.
>
> Actually, the stats socket seems like a really good bet to me, since all
> the backends will be interested in the same socket. The
> client-to-backend sockets are only touched by two processes each, so
> don't seem like big contention sources.

Do we take specific steps to ensure that we don't block when attempting
to write to these sockets? I *think* there's a flag that's associated
with the socket descriptor that determines locking behavior, but I
haven't been able to find a great deal of info.

Right now the only way I can think of to try and reproduce this is to
modify the code so that we're passing a much larger amount of data to
the stats logger and then fire up pgbench. But I know there's been some
discussion about changing things so that we won't drop stats messages,
so maybe it's a moot point.

BTW, this server does have command string logging on, so if this is a
stats issue that probably made the problem worse. Would it be practical
to have backends only log the command string if the command runs for
more than some number of milliseconds? I suspect there's very little
case for actually trying to log every single command, so realistically
people are only going to care about commands that are taking a decent
amount of time.
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

"Jim C. Nasby" <jnasby(at)pervasive(dot)com> writes:
> On Tue, May 02, 2006 at 11:06:59PM -0400, Tom Lane wrote:
>> Actually, the stats socket seems like a really good bet to me, since all
>> the backends will be interested in the same socket. The
>> client-to-backend sockets are only touched by two processes each, so
>> don't seem like big contention sources.

> Do we take specific steps to ensure that we don't block when attempting
> to write to these sockets?

Well, we have the socket set to O_NONBLOCK mode. Whether that avoids
the problem you're seeing ...

> BTW, this server does have command string logging on, so if this is a
> stats issue that probably made the problem worse.

Can you turn that off for a bit and see if it affects things?

regards, tom lane

On Wed, May 03, 2006 at 01:37:03PM -0400, Tom Lane wrote:
> "Jim C. Nasby" <jnasby(at)pervasive(dot)com> writes:
> > On Tue, May 02, 2006 at 11:06:59PM -0400, Tom Lane wrote:
> >> Actually, the stats socket seems like a really good bet to me, since all
> >> the backends will be interested in the same socket. The
> >> client-to-backend sockets are only touched by two processes each, so
> >> don't seem like big contention sources.
>
> > Do we take specific steps to ensure that we don't block when attempting
> > to write to these sockets?
>
> Well, we have the socket set to O_NONBLOCK mode. Whether that avoids
> the problem you're seeing ...

A quick grep through the source code doesn't look too promising, so
maybe that's not the proper way not to block on FBSD. Though Larry was
telling me that there's recently been changes made in the socket code,
so maybe this problem was fixed recently.

> > BTW, this server does have command string logging on, so if this is a
> > stats issue that probably made the problem worse.
>
> Can you turn that off for a bit and see if it affects things?

That would require being able to easily reproduce the problem, which I'm
not sure will be possible, since the site was handling over 400
concurrent requests at a time from the web when this happened. That's
why I'm wondering if it might be a better idea to test on another
machine with a copy of the code that's been hacked to send a big pile of
data to the stats process with every query. That would hopefully allow
pgbench to exhibit the same behavior.
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

We tried reproducing this on a backup server. We haven't been able to
wedge the system into a state where there's tons of sblock processes
and nothing's getting done, but we were able to get some processes into
sblock and get stack traces:

#0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
#1 0x00000000004f9898 in secure_read ()
#2 0x00000000004fed7b in TouchSocketFile ()
#3 0x00000000004fee27 in pq_getbyte ()
#4 0x000000000055febf in PostgresMain ()
#5 0x000000000053a487 in ClosePostmasterPorts ()
#6 0x000000000053bab7 in PostmasterMain ()
#7 0x0000000000500436 in main ()

#0 0x000000080137638c in sendto () from /lib/libc.so.6
#1 0x0000000000535fb5 in pgstat_report_activity ()
#2 0x000000000055fe81 in PostgresMain ()
#3 0x000000000053a487 in ClosePostmasterPorts ()
#4 0x000000000053bab7 in PostmasterMain ()
#5 0x0000000000500436 in main ()

#0 0x000000080137638c in sendto () from /lib/libc.so.6
#1 0x00000000004f954c in secure_write ()
#2 0x00000000004ff295 in pq_getmessage ()
#3 0x00000000004ff480 in pq_flush ()
#4 0x000000000055c59a in ReadyForQuery ()
#5 0x000000000055fe8c in PostgresMain ()
#6 0x000000000053a487 in ClosePostmasterPorts ()
#7 0x000000000053bab7 in PostmasterMain ()
#8 0x0000000000500436 in main ()

It may or may not be important that in the test environment we're not
seeing any 'statistics buffer is full' errors.

One thing that is interesting is that Tom thought that sblock probably
couldn't be happening on the client socket, since once that's
established there won't be any processes vieing for time on it, but I'm
wondering if TouchSocketFile() could be throwing a wrench into the
works? The 1st trace shows that it can put the process into sblock, so
I'm wondering if under certain circumstances that could end up running
away.

BTW, one interesting tidbit out of this is that this dual opteron
machine is handling 2000 transactions per second when we're trying to
reproduce the problem. Granted, these are almost entirely read-only
transactions, but still...

On Tue, May 02, 2006 at 07:38:56PM -0500, Jim C. Nasby wrote:
> Just experienced a server that was spending over 50% of CPU time in the
> system, apparently dealing with postmasters that were in the sblock
> state. Looking at the FreeBSD source, this indicates that the process is
> waiting for a lock on a socket. During this time the machine was doing
> nearly 200k context switches a second.
>
> At the same time, the server was also producing 'statistics buffer is
> full' errors.
>
> Has anyone seen this before? I suspect that the stats buffer errors are
> a symptom and not the cause of the problem, but unfortunately I wasn't
> able to get a stack trace to verify that theory.
>
> The machine is a dual Opteron 250 with 8G of memory, running 8.1.3.
> While this was going on there were between 10 and 250 backends running
> at once, based on vmstat.
>
> Any ideas what areas of the code could be locking a socket?
> Theoretically it shouldn't be the stats collector, and the site is using
> pgpool as a connection pool, so this shouldn't be due to trying to
> connect to backends at a furious rate.
> --
> Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
> Pervasive Software http://pervasive.com work: 512-231-6117
> vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo(at)postgresql(dot)org so that your
> message can get through to the mailing list cleanly
>

--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

Jim C. Nasby wrote:
> We tried reproducing this on a backup server. We haven't been able to
> wedge the system into a state where there's tons of sblock processes
> and nothing's getting done, but we were able to get some processes into
> sblock and get stack traces:
>
> #0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
> #1 0x00000000004f9898 in secure_read ()
> #2 0x00000000004fed7b in TouchSocketFile ()
> #3 0x00000000004fee27 in pq_getbyte ()
> #4 0x000000000055febf in PostgresMain ()
> #5 0x000000000053a487 in ClosePostmasterPorts ()
> #6 0x000000000053bab7 in PostmasterMain ()
> #7 0x0000000000500436 in main ()

This stack trace doesn't make any sense. ClosePostmasterPorts is not
calling PostgresMain. And pq_getbyte is not calling TouchSocketFile,
which in turn isn't calling secure_read.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On Wed, May 10, 2006 at 04:24:45PM -0400, Alvaro Herrera wrote:
> Jim C. Nasby wrote:
> > We tried reproducing this on a backup server. We haven't been able to
> > wedge the system into a state where there's tons of sblock processes
> > and nothing's getting done, but we were able to get some processes into
> > sblock and get stack traces:
> >
> > #0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
> > #1 0x00000000004f9898 in secure_read ()
> > #2 0x00000000004fed7b in TouchSocketFile ()
> > #3 0x00000000004fee27 in pq_getbyte ()
> > #4 0x000000000055febf in PostgresMain ()
> > #5 0x000000000053a487 in ClosePostmasterPorts ()
> > #6 0x000000000053bab7 in PostmasterMain ()
> > #7 0x0000000000500436 in main ()
>
> This stack trace doesn't make any sense. ClosePostmasterPorts is not
> calling PostgresMain. And pq_getbyte is not calling TouchSocketFile,
> which in turn isn't calling secure_read.

So I see... that's rather disturbing... any idea why gdb would end up
that confused?
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

On Wed, May 10, 2006 at 04:52:38PM -0500, Jim C. Nasby wrote:
> On Wed, May 10, 2006 at 04:24:45PM -0400, Alvaro Herrera wrote:
> > Jim C. Nasby wrote:
> > > We tried reproducing this on a backup server. We haven't been able to
> > > wedge the system into a state where there's tons of sblock processes
> > > and nothing's getting done, but we were able to get some processes into
> > > sblock and get stack traces:
> > >
> > > #0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
> > > #1 0x00000000004f9898 in secure_read ()
> > > #2 0x00000000004fed7b in TouchSocketFile ()
> > > #3 0x00000000004fee27 in pq_getbyte ()
> > > #4 0x000000000055febf in PostgresMain ()
> > > #5 0x000000000053a487 in ClosePostmasterPorts ()
> > > #6 0x000000000053bab7 in PostmasterMain ()
> > > #7 0x0000000000500436 in main ()
> >
> > This stack trace doesn't make any sense. ClosePostmasterPorts is not
> > calling PostgresMain. And pq_getbyte is not calling TouchSocketFile,
> > which in turn isn't calling secure_read.
>
> So I see... that's rather disturbing... any idea why gdb would end up
> that confused?

Given you don't have debug enabled, it's likely all static symbols have
been dropped from the symbol table and gdb is guessing by listing the
function with the highest address before the actual function.

You could try to find a consistant call tree where the functions call
eachother in the right order. Or just compile with debug symbols
enabled. It doesn't make a difference in performance or memory usage,
only diskspace (about 16MB on my machine, probably more on yours).

Have a nice day,
--
Martijn van Oosterhout <kleptog(at)svana(dot)org> http://svana.org/kleptog/
> From each according to his ability. To each according to his ability to litigate.

On Thu, May 11, 2006 at 12:09:32AM +0200, Martijn van Oosterhout wrote:
> > > This stack trace doesn't make any sense. ClosePostmasterPorts is not
> > > calling PostgresMain. And pq_getbyte is not calling TouchSocketFile,
> > > which in turn isn't calling secure_read.
> >
> > So I see... that's rather disturbing... any idea why gdb would end up
> > that confused?
>
> Given you don't have debug enabled, it's likely all static symbols have
> been dropped from the symbol table and gdb is guessing by listing the
> function with the highest address before the actual function.
>
> You could try to find a consistant call tree where the functions call
> eachother in the right order. Or just compile with debug symbols
> enabled. It doesn't make a difference in performance or memory usage,
> only diskspace (about 16MB on my machine, probably more on yours).

Yeah, I was actually surprised when gdb spit out real function names and
not just gibberish since I assumed that PostgreSQL wasn't compiled with
debug symbols. I thought my assumption was wrong when that stuff came
out, but I guess that was a bad guess...

I'll recompile and try again... thanks!
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

On Wed, May 10, 2006 at 05:23:29PM -0500, Jim C. Nasby wrote:
> On Thu, May 11, 2006 at 12:09:32AM +0200, Martijn van Oosterhout wrote:
> > > > This stack trace doesn't make any sense. ClosePostmasterPorts is not
> > > > calling PostgresMain. And pq_getbyte is not calling TouchSocketFile,
> > > > which in turn isn't calling secure_read.
> > >
> > > So I see... that's rather disturbing... any idea why gdb would end up
> > > that confused?
> >
> > Given you don't have debug enabled, it's likely all static symbols have
> > been dropped from the symbol table and gdb is guessing by listing the
> > function with the highest address before the actual function.
> >
> > You could try to find a consistant call tree where the functions call
> > eachother in the right order. Or just compile with debug symbols
> > enabled. It doesn't make a difference in performance or memory usage,
> > only diskspace (about 16MB on my machine, probably more on yours).
>
> Yeah, I was actually surprised when gdb spit out real function names and
> not just gibberish since I assumed that PostgreSQL wasn't compiled with
> debug symbols. I thought my assumption was wrong when that stuff came
> out, but I guess that was a bad guess...
>
> I'll recompile and try again... thanks!

Ok, got some good traces this time, with debug. Even better, by upping
the number of pgpool connections to 395, we were able to exactly
duplicate the problem we saw earlier in production (I know, who'd think
a dual opteron would have trouble servicing 400 simultaneous connections
at once? ;)

Unfortunately, I suspect some of these were grabbed after the process
had already moved past whatever was holding it in sblock.

Here's the traces that we captured...

Got 2 of these:
#0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
#1 0x00000000004f9898 in secure_read (port=0x834800, ptr=0x7cebe0,
len=8192) at be-secure.c:320
#2 0x00000000004fed7b in pq_recvbuf () at pqcomm.c:697
#3 0x00000000004fee27 in pq_getbyte () at pqcomm.c:738
#4 0x000000000055febf in PostgresMain (argc=4, argv=0x83b828,
username=0x83b740 "www") at postgres.c:289
#5 0x000000000053a487 in ServerLoop () at postmaster.c:2851
#6 0x000000000053bab7 in PostmasterMain (argc=3,
argv=0x7fffffffebb0) at postmaster.c:941
#7 0x0000000000500436 in main (argc=3, argv=0x7fffffffebb0) at
main.c:265

#0 0x000000080137638c in sendto () from /lib/libc.so.6
#1 0x0000000000535e67 in pgstat_report_tabstat () at pgstat.c:846
#2 0x000000000055ff75 in PostgresMain (argc=4, argv=0x83b828,
username=0x83b740 "www") at postgres.c:3162
#3 0x000000000053a487 in ServerLoop () at postmaster.c:2851
#4 0x000000000053bab7 in PostmasterMain (argc=3,
argv=0x7fffffffebb0) at postmaster.c:941
#5 0x0000000000500436 in main (argc=3, argv=0x7fffffffebb0) at
main.c:265

I suspect the rest of these probably happened after the sblock state had
cleared, but here they are anyway in case I'm wrong. Also, I removed the
'incriminating evidence' from the query strings; there wasn't anything
unusual about those queries, so I don't think it should matter.

#0 0x000000080138fcec in __syscall () from /lib/libc.so.6
#1 0x000000000054e67f in FileSeek (file=199, offset=0, whence=2) at
fd.c:1173
#2 0x000000000055aca3 in mdnblocks (reln=0x9f68c0) at md.c:972
#3 0x000000000055bb4a in smgrnblocks (reln=0x9f68c0) at smgr.c:571
#4 0x000000000052fbde in get_relation_info (relationObjectId=199,
rel=0xad3728) at plancat.c:206
#5 0x0000000000531041 in make_reloptinfo (root=0xac13e0, relid=6,
reloptkind=RELOPT_BASEREL) at relnode.c:146
#6 0x0000000000521ed3 in add_base_rels_to_query (root=0xac13e0,
jtnode=0xad2600) at initsplan.c:88
#7 0x0000000000521e93 in add_base_rels_to_query (root=0xac13e0,
jtnode=0xac9cd8) at initsplan.c:94
#8 0x0000000000521ed3 in add_base_rels_to_query (root=0xac13e0,
jtnode=0xad2710) at initsplan.c:88
#9 0x00000000005238cf in query_planner (root=0xac13e0,
tlist=0xace648, tuple_fraction=10, cheapest_path=0x7fffffffd308,
sorted_path=0x7fffffffd310, num_groups=0x7fffffffd318) at
planmain.c:141
#10 0x00000000005240cb in grouping_planner (root=0xac13e0,
tuple_fraction=10) at planner.c:796
#11 0x00000000005252c2 in subquery_planner (parse=0x9f0140,
tuple_fraction=0, subquery_pathkeys=0x0) at planner.c:374
#12 0x0000000000525423 in planner (parse=0x9f0140, isCursor=0 '\0',
cursorOptions=0, boundParams=0x0) at planner.c:134
#13 0x000000000055ddec in pg_plan_query (querytree=0x9f0140,
boundParams=0x0) at postgres.c:725
#14 0x000000000055de7c in pg_plan_queries (querytrees=0xc7,
boundParams=0x0, needSnapshot=0 '\0') at postgres.c:793
#15 0x000000000055e986 in exec_simple_query (
query_string=0x9f0250 "<snip>"...) at postgres.c:944
#16 0x000000000056031e in PostgresMain (argc=4, argv=0x83b828,
username=0x83b740 "www") at postgres.c:3217
#17 0x000000000053a487 in ServerLoop () at postmaster.c:2851
#18 0x000000000053bab7 in PostmasterMain (argc=3,
argv=0x7fffffffebb0) at postmaster.c:941
#19 0x0000000000500436 in main (argc=3, argv=0x7fffffffebb0) at
main.c:265

#0 hash_search (hashp=0x83b3f0, keyPtr=0x7fffffffd090,
action=HASH_FIND, foundPtr=0x0) at dynahash.c:585
#1 0x000000000054aa47 in BufTableLookup (tagPtr=0x7fffffffd09c) at
buf_table.c:82
#2 0x000000000054bbfd in ReadBuffer (reln=0xa24050, blockNum=7811)
at bufmgr.c:310
#3 0x000000000044a7c5 in heap_release_fetch (relation=0xa24050,
snapshot=0xa1f830, tuple=0xab7930, userbuf=0xab7950, keep_buf=1 '\001',
pgstat_info=0xab7960) at heapam.c:851
#4 0x000000000045043e in index_getnext (scan=0xab78e8,
direction=ForwardScanDirection) at indexam.c:547
#5 0x00000000004ef543 in IndexNext (node=0xab6530) at
nodeIndexscan.c:118
#6 0x00000000004e837f in ExecScan (node=0xab6530, accessMtd=0x4ef4c0
<IndexNext>) at execScan.c:103
#7 0x00000000004e38bd in ExecProcNode (node=0xab6530) at
execProcnode.c:325
#8 0x00000000004f13a1 in ExecNestLoop (node=0xa20880) at
nodeNestloop.c:135
#9 0x00000000004e386d in ExecProcNode (node=0xa20880) at
execProcnode.c:350
#10 0x00000000004f26d3 in ExecSort (node=0xa20770) at nodeSort.c:101
#11 0x00000000004e382a in ExecProcNode (node=0xa20770) at
execProcnode.c:369
#12 0x00000000004f2d43 in ExecLimit (node=0xa20550) at nodeLimit.c:84
#13 0x00000000004e37cd in ExecProcNode (node=0xa20550) at
execProcnode.c:393
#14 0x00000000004e2ad2 in ExecutorRun (queryDesc=0xa20550,
direction=ForwardScanDirection, count=0) at execMain.c:1110
#15 0x0000000000561e18 in PortalRunSelect (portal=0xa05030,
forward=-64 '?', count=0, dest=0xab2dd0) at pquery.c:794
#16 0x00000000005624bf in PortalRun (portal=0xa05030,
count=9223372036854775807, dest=0xab2dd0, altdest=0xab2dd0,
completionTag=0x7fffffffd5f0 "")
at pquery.c:646
#17 0x000000000055ea36 in exec_simple_query (
query_string=0x9f3250 "<snip>"...) at postgres.c:1002
#18 0x000000000056031e in PostgresMain (argc=4, argv=0x83b828,
username=0x83b740 "www") at postgres.c:3217
#19 0x000000000053a487 in ServerLoop () at postmaster.c:2851
#20 0x000000000053bab7 in PostmasterMain (argc=3,
argv=0x7fffffffebb0) at postmaster.c:941
#21 0x0000000000500436 in main (argc=3, argv=0x7fffffffebb0) at
main.c:265

#0 0x00000008013190ec in semop () from /lib/libc.so.6
#1 0x0000000000532da0 in PGSemaphoreUnlock (sema=0x87b837920) at
pg_sema.c:443
#2 0x000000000055949c in LWLockRelease (lockid=LockMgrLock) at
lwlock.c:554
#3 0x00000000005557b2 in LockAcquire (lockmethodid=1,
locktag=0x7fffffffd270, isTempObject=-120 '\210', lockmode=1,
sessionLock=-72 '?',
dontWait=0 '\0') at lock.c:771
#4 0x0000000000554544 in LockRelation (relation=0xa4d318,
lockmode=0) at lmgr.c:144
#5 0x000000000044fec8 in index_beginscan_internal
(indexRelation=0xa4d318, nkeys=1, key=0xaa5df8) at indexam.c:300
#6 0x000000000044ff7e in index_beginscan_multi
(indexRelation=0x20011, snapshot=0xaa3030, nkeys=-11904, key=0x0) at
indexam.c:267
#7 0x00000000004edb5a in ExecInitBitmapIndexScan (node=0xab5c20,
estate=0xaa4030) at nodeBitmapIndexscan.c:286
#8 0x00000000004e3685 in ExecInitNode (node=0xab5c20,
estate=0xaa4030) at execProcnode.c:167
#9 0x00000000004ecf6e in ExecInitBitmapOr (node=0xab5dd0,
estate=0xaa4030) at nodeBitmapOr.c:87
#10 0x00000000004e36b5 in ExecInitNode (node=0xab6ae0,
estate=0xaa4030) at execProcnode.c:152
#11 0x00000000004ed82a in ExecInitBitmapHeapScan (node=0xab7198,
estate=0xaa4030) at nodeBitmapHeapscan.c:501
#12 0x00000000004e3675 in ExecInitNode (node=0xab7198,
estate=0xaa4030) at execProcnode.c:171
#13 0x00000000004e1c42 in ExecutorStart (queryDesc=0xaa3440,
explainOnly=-128 '\200') at execMain.c:617
#14 0x0000000000561a0c in PortalStart (portal=0xa05030, params=0x0,
snapshot=0x0) at pquery.c:399
#15 0x000000000055e9d8 in exec_simple_query (
query_string=0x9f3030 "<snip>") at postgres.c:965
#16 0x000000000056031e in PostgresMain (argc=4, argv=0x83b828,
username=0x83b740 "www") at postgres.c:3217
#17 0x000000000053a487 in ServerLoop () at postmaster.c:2851
#18 0x000000000053bab7 in PostmasterMain (argc=3,
argv=0x7fffffffebb0) at postmaster.c:941
#19 0x0000000000500436 in main (argc=3, argv=0x7fffffffebb0) at
main.c:265
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

On Thu, May 11, 2006 at 12:09:56PM -0500, Jim C. Nasby wrote:
> Unfortunately, I suspect some of these were grabbed after the process
> had already moved past whatever was holding it in sblock.
>
> Here's the traces that we captured...
>
> Got 2 of these:
> #0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
> #1 0x00000000004f9898 in secure_read (port=0x834800, ptr=0x7cebe0, len=8192) at be-secure.c:320

This is an idle backend waiting for the user.

> #0 0x000000080137638c in sendto () from /lib/libc.so.6
> #1 0x0000000000535e67 in pgstat_report_tabstat () at pgstat.c:846

This definitly the statistics collector, which is something that was
speculated upthread. Do you get a lot of these?

> I suspect the rest of these probably happened after the sblock state had
> cleared, but here they are anyway in case I'm wrong. Also, I removed the
> 'incriminating evidence' from the query strings; there wasn't anything
> unusual about those queries, so I don't think it should matter.

The rest look like backends going through normal query functions...
There was one waiting for a lock but that's unlikely to be
significant...

Hope this helps,
--
Martijn van Oosterhout <kleptog(at)svana(dot)org> http://svana.org/kleptog/
> From each according to his ability. To each according to his ability to litigate.

On Thu, May 11, 2006 at 07:39:23PM +0200, Martijn van Oosterhout wrote:
> On Thu, May 11, 2006 at 12:09:56PM -0500, Jim C. Nasby wrote:
> > Unfortunately, I suspect some of these were grabbed after the process
> > had already moved past whatever was holding it in sblock.
> >
> > Here's the traces that we captured...
> >
> > Got 2 of these:
> > #0 0x000000080135bd2c in recvfrom () from /lib/libc.so.6
> > #1 0x00000000004f9898 in secure_read (port=0x834800, ptr=0x7cebe0, len=8192) at be-secure.c:320
>
> This is an idle backend waiting for the user.

So why would that be waiting to lock the socket? My understanding is
that nothing else should be contending for that socket, no?

> > #0 0x000000080137638c in sendto () from /lib/libc.so.6
> > #1 0x0000000000535e67 in pgstat_report_tabstat () at pgstat.c:846
>
> This definitly the statistics collector, which is something that was
> speculated upthread. Do you get a lot of these?

I included everything that was captured, but of course that's only a
small sampling. If it's helpful we could probably setup something that
would automatically grab stack traces for a larger number of backends
and then see how many were in that state.

What's interesting is that while we were able to re-create the same
state, this time we didn't see any messages in the log about the
statistics collector filling it's buffer.

BTW, I should point out that the goal is to try and ensure that the
machine doesn't end up in a state where all the CPU is going to system
calls, but I'm suspecting that maybe this is an OS issue and not a
PostgreSQL issue at this point...

> > I suspect the rest of these probably happened after the sblock state had
> > cleared, but here they are anyway in case I'm wrong. Also, I removed the
> > 'incriminating evidence' from the query strings; there wasn't anything
> > unusual about those queries, so I don't think it should matter.
>
> The rest look like backends going through normal query functions...
> There was one waiting for a lock but that's unlikely to be
> significant...

Yeah, my suspicion is that those processes had moved past waiting on the
socket lock by the time gdb got to them. Any idea of how you could tell
what state (as reported by top) the process was in when gdb stopped it?
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

On Thu, May 11, 2006 at 02:39:14PM -0500, Jim C. Nasby wrote:
> On Thu, May 11, 2006 at 07:39:23PM +0200, Martijn van Oosterhout wrote:
> > This is an idle backend waiting for the user.
>
> So why would that be waiting to lock the socket? My understanding is
> that nothing else should be contending for that socket, no?

I'm not sure about locks, but it will be blocking on the socket...

> > > #0 0x000000080137638c in sendto () from /lib/libc.so.6
> > > #1 0x0000000000535e67 in pgstat_report_tabstat () at pgstat.c:846
> >
> > This definitly the statistics collector, which is something that was
> > speculated upthread. Do you get a lot of these?
>
> I included everything that was captured, but of course that's only a
> small sampling. If it's helpful we could probably setup something that
> would automatically grab stack traces for a larger number of backends
> and then see how many were in that state.

If you know the pids you should be able to within gdb just do
attach/bt/detech. gdb has some redimentary scripting capabilites so you
might be able to do this fairly quickly.

> Yeah, my suspicion is that those processes had moved past waiting on the
> socket lock by the time gdb got to them. Any idea of how you could tell
> what state (as reported by top) the process was in when gdb stopped it?

Heh. Attaching to a process has the same effect as sending it a signal.
Any active system call is aborted and gdb traps it as it goes to
userspace. So by definition it's in running state when gdb gets it ...

Have a nice day,
--
Martijn van Oosterhout <kleptog(at)svana(dot)org> http://svana.org/kleptog/
> From each according to his ability. To each according to his ability to litigate.

Jim C. Nasby wrote:

> Yeah, my suspicion is that those processes had moved past waiting on the
> socket lock by the time gdb got to them. Any idea of how you could tell
> what state (as reported by top) the process was in when gdb stopped it?

I think you could send SIGSTOP to all backends at once, then grab the
backtraces with GDB, then restart them. That way, all backends will
appear to be in the same frozen state, instead of having some in an
"earlier" state than others.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On Thu, May 11, 2006 at 09:50:14PM +0200, Martijn van Oosterhout wrote:
> On Thu, May 11, 2006 at 02:39:14PM -0500, Jim C. Nasby wrote:
> > On Thu, May 11, 2006 at 07:39:23PM +0200, Martijn van Oosterhout wrote:
> > > This is an idle backend waiting for the user.
> >
> > So why would that be waiting to lock the socket? My understanding is
> > that nothing else should be contending for that socket, no?
>
> I'm not sure about locks, but it will be blocking on the socket...

Yeah, talking to AndrewSN and some others on IRC they're wondering if
maybe it's running out of network buffers, which could possibly cause
this.

> > > > #0 0x000000080137638c in sendto () from /lib/libc.so.6
> > > > #1 0x0000000000535e67 in pgstat_report_tabstat () at pgstat.c:846
> > >
> > > This definitly the statistics collector, which is something that was
> > > speculated upthread. Do you get a lot of these?
> >
> > I included everything that was captured, but of course that's only a
> > small sampling. If it's helpful we could probably setup something that
> > would automatically grab stack traces for a larger number of backends
> > and then see how many were in that state.
>
> If you know the pids you should be able to within gdb just do
> attach/bt/detech. gdb has some redimentary scripting capabilites so you
> might be able to do this fairly quickly.

Yeah, what I was thinking. But now that we've been investigating this
more I'm suspecting this is more a matter of tuning over it being a
possible bug. It turns out we have to be doing over 2000 queries per
second on this dual opteron before the problem will happen...

> > Yeah, my suspicion is that those processes had moved past waiting on the
> > socket lock by the time gdb got to them. Any idea of how you could tell
> > what state (as reported by top) the process was in when gdb stopped it?
>
> Heh. Attaching to a process has the same effect as sending it a signal.
> Any active system call is aborted and gdb traps it as it goes to
> userspace. So by definition it's in running state when gdb gets it ...

Heh, yeah... oh well.
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461