public inbox for [email protected]  
help / color / mirror / Atom feed
From: torikoshia <[email protected]>
To: James Coleman <[email protected]>
Cc: Andres Freund <[email protected]>
Cc: [email protected]
Cc: Greg Stark <[email protected]>
Cc: Ronan Dunklau <[email protected]>
Cc: [email protected]
Cc: Heikki Linnakangas <[email protected]>
Subject: Re: RFC: Logging plan of the running query
Date: Thu, 07 Sep 2023 15:09:12 +0900
Message-ID: <[email protected]> (raw)
In-Reply-To: <CAAaqYe_hyWLs-ObFQfu54yA-ZOjNCd-L_Z=1TnYjYNqrLuGiXQ@mail.gmail.com>
References: <[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<[email protected]>
	<CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw@mail.gmail.com>
	<[email protected]>
	<CAAaqYe8LXVXQhYy3yT0QOHUymdM=uha0dJ0=BEPzVAx2nG1gsw@mail.gmail.com>
	<[email protected]>
	<CAAaqYe9u-ywvRX32iBj1SkQrLf1hqMhR9HFCc0dAk4rGDJpyFw@mail.gmail.com>
	<[email protected]>
	<CAAaqYe-5jKTuuZB5StBwa2YRiqpnN=q9buKADP8A_RPd09f_Ug@mail.gmail.com>
	<CAAaqYe-M63VNMpgq0sEw3+t2KaJyhXfu3uBU7w_jtfbGAm4LoA@mail.gmail.com>
	<[email protected]>
	<CAAaqYe9QB_CUjXrvNh-cpzW6Hz7S4o5pZnR1U1TujLGptUrS1A@mail.gmail.com>
	<[email protected]>
	<[email protected]>
	<CAAaqYe9TPyWe9yoOm5Jz_39gSnhCAYXozc698jkyegM1x74Qjg@mail.gmail.com>
	<CAAaqYe9Mse7JC78DgT97sXoB6U+E5OL3zJAYRSsgy-TPP9PXmw@mail.gmail.com>
	<[email protected]>
	<CAAaqYe_5p_MkBCgSYX=S7G3ZKi=2=_6bZQFzTgVYyv=1NRikpw@mail.gmail.com>
	<[email protected]>
	<CAAaqYe_hyWLs-ObFQfu54yA-ZOjNCd-L_Z=1TnYjYNqrLuGiXQ@mail.gmail.com>

On 2023-09-06 11:17, James Coleman wrote:

>> > I've never been able to reproduce it (haven't tested the new version,
>> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
>> > (first buster and now bullseye).
>> >
>> > I'm attaching several stacktraces in the hope that they provide some
>> > clues. These all match the ps output I sent earlier, though note in
>> > that output there is both the regress instance and my test instance
>> > (pid 3213249) running (different ports, of course, and they are from
>> > the exact same compilation run). I've attached ps output for the
>> > postgres processes under the make check process to simplify cross
>> > referencing.
>> >
>> > A few interesting things:
>> > - There's definitely a lock on a relation that seems to be what's
>> > blocking the processes.
>> > - When I try to connect with psql the process forks but then hangs
>> > (see the ps output with task names stuck in "authentication"). I've
>> > also included a trace from one of these.
>> 
>> Thanks for sharing them!
>> 
>> Many processes are waiting to acquire the LW lock, including the 
>> process
>> trying to output the plan(select1.trace).
>> 
>> I suspect that this is due to a lock that was acquired prior to being
>> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able 
>> to
>> reproduce the same situation..
>> 
> 
> I don't have time immediately to dig into this, but perhaps loading up
> the core dumps would allow us to see what query is running in each
> backend process (if it hasn't already been discarded by that point)
> and thereby determine what point in each test process led to the error
> condition?

Thanks for the suggestion.
I am concerned that core dumps may not be readable on different 
operating systems or other environments. (Unfortunately, I do not have 
Debian on hand)

It seems that we can know what queries were running from the stack 
traces you shared.
As described above, I suspect a lock which was acquired prior to 
ProcessLogQueryPlanInterrupt() caused the issue.
I will try a little more to see if I can devise a way to create the same 
situation.

> Alternatively we might be able to apply the same trick to the test
> client instead...
> 
> BTW, for my own easy reference in this thread: relid 1259 is pg_class
> if I'm not mistaken.

Yeah, and I think it's strange that the lock to 1259 appears twice and 
must be avoided.

   #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at 
lmgr.c:117
   ..
   #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at 
explain.c:5158
   ..
   #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at 
lmgr.c:117

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation






view thread (25+ messages)  latest in thread

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: [email protected]
  Cc: [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected]
  Subject: Re: RFC: Logging plan of the running query
  In-Reply-To: <[email protected]>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox