Received: from localhost (unknown [200.46.204.183])
	by postgresql.org (Postfix) with ESMTP id C3B432E0041
	for <pgsql-performance-postgresql.org@postgresql.org>;
	Wed, 27 Feb 2008 22:19:24 -0400 (AST)
Received: from postgresql.org ([200.46.204.71])
	by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024)
	with ESMTP id 12827-07 for
	<pgsql-performance-postgresql.org@postgresql.org>;
	Wed, 27 Feb 2008 22:19:21 -0400 (AST)
X-Greylist: domain auto-whitelisted by SQLgrey-1.7.5
Received: from smtpoutm.mac.com (smtpoutm.mac.com [17.148.16.67])
	by postgresql.org (Postfix) with ESMTP id EC9102E004F
	for <pgsql-performance@postgresql.org>;
	Wed, 27 Feb 2008 22:19:20 -0400 (AST)
Received: from mac.com (asmtp010-s [10.150.69.73])
	by smtpoutm.mac.com (Xserve/smtpout004/MantshX 4.0) with ESMTP id
	m1S2JJJ9012525; Wed, 27 Feb 2008 18:19:19 -0800 (PST)
Received: from [192.168.0.9] ([38.99.35.195]) (authenticated bits=0)
	by mac.com (Xserve/asmtp010/MantshX 4.0) with ESMTP id m1S2JHCA007500
	(version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO);
	Wed, 27 Feb 2008 18:19:17 -0800 (PST)
Mime-Version: 1.0
Message-Id: <p06240825c3ea751d3cda@[192.168.0.9]>
In-Reply-To: <9501.1204066918@sss.pgh.pa.us>
References: <p06240804c3e61871f289@[10.0.1.253]>
	<5576.1203795335@sss.pgh.pa.us> <p06240806c3e67e31cbd0@[10.0.1.253]>
	<6730.1203829093@sss.pgh.pa.us> <p06240812c3e9ea5ea7f8@[10.0.1.253]>
	<5080.1204047806@sss.pgh.pa.us> <p06240818c3ea092cf31b@[192.168.0.9]>
	<9501.1204066918@sss.pgh.pa.us>
Date: Wed, 27 Feb 2008 18:19:12 -0800
To: Tom Lane <tgl@sss.pgh.pa.us>
From: Joel Stevenson <joelstevenson@mac.com>
Subject: Re: LISTEN / NOTIFY performance in 8.3
Cc: pgsql-performance@postgresql.org
Content-Type: text/plain; charset="us-ascii" ; format="flowed"
X-Virus-Scanned: Maia Mailguard 1.0.1
X-Spam-Status: No, hits=0 tagged_above=0 required=5 tests=none
X-Spam-Level: 
X-Archive-Number: 200802/390
X-Sequence-Number: 28932

At 6:01 PM -0500 2/26/08, Tom Lane wrote:
>Hmm, that says that it's not a matter of locking on pg_listener,
>but of actually applying the row update(s) and/or signaling the
>recipient(s).  If you're not seeing performance issues for ordinary
>table-update operations it's hard to see why pg_listener updates would
>be any worse, so that seems to point the finger at the signaling.
>Which is just a matter of a kill(2) and shouldn't be that expensive.
>
>It might be interesting to try strace'ing the whole PG process tree
>while these notifies are going on, and seeing if you can identify
>any specific kernel calls that seem to take a long time.

I ran PG via strace and then ran the test script at 25 consumers 
looping 25 times each.  There were no other connections to the 
database for this strace run and test.

Digging through the strace file is a bit mind-numbing but here's some 
signs that semop and send are the culprits:

3 misc examples coming from near LISTEN or NOTIFIES:
- - - - - -
7495  18:10:40.251855 <... semop resumed> ) = 0 <1.006149>
7495  18:10:41.325442 <... semop resumed> ) = -1 EINTR (Interrupted 
system call) <0.299135>
7495  18:10:41.998219 <... semop resumed> ) = 0 <0.603566>

A chunk of log following the action on fd 7 (slow recv on 
ERESTARTSYS) and then the slow semop that follows:
- - - - - - - -
7495  18:10:42.576401 send(7, "C\0\0\0\vNOTIFY\0Z\0\0\0\5I", 18, 0 
<unfinished ...>
7495  18:10:42.576503 <... send resumed> ) = 18 <0.000070>
7495  18:10:42.576620 recv(7,  <unfinished ...>
7495  18:10:42.873796 <... recv resumed> 0x8331d40, 8192, 0) = ? 
ERESTARTSYS (To be restarted) <0.297158>
7495  18:10:42.873911 --- SIGUSR2 (User defined signal 2) @ 0 (0) ---
7495  18:10:42.874079 gettimeofday( <unfinished ...>
7495  18:10:42.874198 <... gettimeofday resumed> {1204078242, 
874097}, NULL) = 0 <0.000101>
7495  18:10:42.874324 setitimer(ITIMER_REAL, {it_interval={0, 0}, 
it_value={1, 0}},  <unfinished ...>
7495  18:10:42.874470 <... setitimer resumed> NULL) = 0 <0.000121>
7495  18:10:42.874604 semop(50495522, 0xbfff9764, 1 <unfinished ...>
7495  18:10:43.678431 <... semop resumed> ) = 0 <0.803809>

A little further on:
- - - - - - - -
7495  18:10:44.905320 <... semop resumed> ) = -1 EINTR (Interrupted 
system call) <0.998192>


I'm not sure what exactly that means, in terms of next steps.  I'll 
dig more through the strace file and see if I can find anything else 
but those look to be definite bottlenecks for some reason.

At 2:24 PM -0800 2/26/08, Maurice Aubrey wrote:
>What's the OS/Dist?

Red Hat Enterprise Linux ES release 3 (Taroon Update 8)

Thx,
-Joel