Re: BUG #3504: Some listening sessions never return from writing, problems ensue

It looks to me that the server is trying to send stuff to the client,
but the client is not reading it for some reason. There's nothing in the
queues in the direction client->server.

What exactly is the client doing? How does it connect to the server,
with libpq? Is it possible that the client is just leaking the
connection, keeping it open but not using it for anything?

Peter Koczan wrote:
> Whoops, a couple quick changes. This:
> [koczan(at)ator] koczan $ ssh newton netstat | grep vero
> tcp 64260 0 newton.cs.wisc.edu:32778
> vero.cs.wisc.edu:postgresqlESTABLISHED
> tcp 0 0 newton.cs.wisc.edu:32777
> vero.cs.wisc.edu:postgresqlESTABLISHED
>
> should be this:
> [koczan(at)ator] koczan $ ssh newton netstat | grep vero
> tcp 64530 0 newton.cs.wisc.edu:32778
> vero.cs.wisc.edu:postgresqlESTABLISHED
> tcp 0 0 newton.cs.wisc.edu:32777
> vero.cs.wisc.edu:postgresqlESTABLISHED
>
> Also, the Send-Q column on the server side doesn't change, even after more
> async notifies. They may not have happened at the same time, but it's a bit
> perplexing that they all have the exact same amount of data in the queue.
>
> Peter
>
> On 8/2/07, Peter Koczan <pjkoczan(at)gmail(dot)com> wrote:
>> I found something pretty interesting when running netstat's:
>>
>> Before a series of 3 async notifies (second column is Recv-Q):
>>
>> OK connections:
>> [koczan(at)ator] koczan $ netstat | grep vero
>> tcp 180 0 ator.cs.wisc.edu:32785
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 ator.cs.wisc.edu:32784
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> [koczan(at)ator] koczan $ ssh newton netstat | grep vero
>> tcp 64260 0 newton.cs.wisc.edu:32778
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 newton.cs.wisc.edu:32777
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>>
>> "notify interrupt" connections:
>> [koczan(at)ator] koczan $ ssh brian netstat | grep vero
>> tcp 0 0 brian.cs.wisc.edu:40365
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 77800 0 brian.cs.wisc.edu:40366
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> [koczan(at)ator] koczan $ ssh zim netstat | grep vero
>> tcp 73402 0 zim.cs.wisc.edu:32777
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 zim.cs.wisc.edu:32776
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>>
>> and after said notifies:
>>
>> OK connections:
>> [koczan(at)ator] koczan $ netstat | grep vero
>> tcp 450 0 ator.cs.wisc.edu:32785
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 ator.cs.wisc.edu:32784
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> [koczan(at)ator] koczan $ ssh newton netstat | grep vero
>> tcp 64260 0 newton.cs.wisc.edu:32778
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 newton.cs.wisc.edu:32777
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>>
>> "notify interrupt" connections:
>> [koczan(at)ator] koczan $ ssh brian netstat | grep vero
>> tcp 0 0 brian.cs.wisc.edu:40365
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 77800 0 brian.cs.wisc.edu:40366
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> [koczan(at)ator] koczan $ ssh zim netstat | grep vero
>> tcp 73402 0 zim.cs.wisc.edu:32777
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>> tcp 0 0 zim.cs.wisc.edu:32776
>> vero.cs.wisc.edu:postgresql ESTABLISHED
>>
>> And on the server side things get a little more interesting (Send-Q is the
>> 3rd column)...
>>
>> OK:
>> [koczan(at)vero] ~ $ netstat | grep ator
>> tcp 0 0 vero.cs.wisc.edu:postgresql ator.cs.wisc.edu:32785
>> ESTABLISHED
>> tcp 0 0 vero.cs.wisc.edu:postgresql ator.cs.wisc.edu:32784
>> ESTABLISHED
>> [koczan(at)vero] ~ $ netstat | grep newton
>> tcp 0 0 vero.cs.wisc.edu:postgresql newton.cs.wisc.edu:32778
>> ESTABLISHED
>> tcp 0 0 vero.cs.wisc.edu:postgresql newton.cs.wisc.edu:32777
>> ESTABLISHED
>>
>> "notify interrupt":
>> [koczan(at)vero] ~ $ netstat | grep brian
>> tcp 0 0 vero.cs.wisc.edu:postgresql brian.cs.wisc.edu:40365
>> ESTABLISHED
>> tcp 0 13032 vero.cs.wisc.edu:postgresql brian.cs.wisc.edu:40366
>> ESTABLISHED
>> [koczan(at)vero] ~ $ netstat | grep zim
>> tcp 0 13032 vero.cs.wisc.edu:postgresql zim.cs.wisc.edu:32777
>> ESTABLISHED
>> tcp 0 0 vero.cs.wisc.edu:postgresql zim.cs.wisc.edu:32776
>> ESTABLISHED
>>
>> A quick perusal of the other "notify interrupt" connections shows 13032 in
>> the Send-Q column. They all got into this state at the same time.
>>
>> Peter
>>
>> P.S. Thanks for the help, I really appreciate it.
>>
>> On 8/2/07, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us > wrote:
>>> Peter Koczan <pjkoczan(at)gmail(dot)com > writes:
>>>> Heikki Linnakangas wrote:
>>>>> Does the client read the async notifies? The write in the server will
>>>>> block if the client doesn't keep up with reading the data.
>>>>>
>>>> Well, the client updates it's GUI properly no matter whether the
>>>> listening session is blocked or not (it's an ongoing tail of
>>> requests).
>>>> Overtly from the client side, it's completely transparent. Is there
>>> any
>>>> way I can tell definitively from the client side whether or not it's
>>>> actually reading the async notifies?
>>> netstat's Recv-Q column would probably reflect it if the client is
>>> failing to consume messages. The send queue on the server side would be
>>> worth checking too.
>>>
>>> regards, tom lane
>>>
>>
>

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com