MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8;
 format=flowed
Content-Transfer-Encoding: 8bit
Date: Thu, 15 Jun 2023 22:00:46 +0900
From: torikoshia <torikoshia@oss.nttdata.com>
To: James Coleman <jtc331@gmail.com>
Cc: Andres Freund <andres@anarazel.de>, pgsql-hackers@lists.postgresql.org,
 Greg Stark <stark@mit.edu>, Ronan Dunklau <ronan.dunklau@aiven.io>,
 david.christensen@crunchydata.com, Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: RFC: Logging plan of the running query
In-Reply-To: <CAAaqYe-M63VNMpgq0sEw3+t2KaJyhXfu3uBU7w_jtfbGAm4LoA@mail.gmail.com>
References: <3bb7bacbc5ef9e58e2ece0557adac98b@oss.nttdata.com>
 <03c8dcbb-72d2-d3ad-3ad1-9efe69676529@oss.nttdata.com>
 <20220208.171852.1699766364147189900.horikyota.ntt@gmail.com>
 <ab761e68f3fbcee80cf1ca19b1db85f1@oss.nttdata.com>
 <3e94e9b3-83ef-c328-0c5c-f93aa3224790@oss.nttdata.com>
 <3d121ed5f81cef588bac836b43f5d1f9@oss.nttdata.com>
 <379d69c0b3d058997550f88e73ffddd6@oss.nttdata.com>
 <727712bcaa8d449615820c16d15e452e@oss.nttdata.com>
 <598171663576373@mail.yandex.ru>
 <38f4e19323b264e5975c60010b512b15@oss.nttdata.com>
 <20221206184101.exj2zyhmt7ta5fco@awork3.anarazel.de>
 <c51098ac613f908776e5564a7c7a0e16@oss.nttdata.com>
 <CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw@mail.gmail.com>
 <2f466f82de025f745dff9377a368cee4@oss.nttdata.com>
 <CAAaqYe8LXVXQhYy3yT0QOHUymdM=uha0dJ0=BEPzVAx2nG1gsw@mail.gmail.com>
 <788e5db60b6c5de4b73fc9810b635d44@oss.nttdata.com>
 <CAAaqYe9u-ywvRX32iBj1SkQrLf1hqMhR9HFCc0dAk4rGDJpyFw@mail.gmail.com>
 <9c3445ab0f695dbd0a879cf380f313c5@oss.nttdata.com>
 <CAAaqYe-5jKTuuZB5StBwa2YRiqpnN=q9buKADP8A_RPd09f_Ug@mail.gmail.com>
 <CAAaqYe-M63VNMpgq0sEw3+t2KaJyhXfu3uBU7w_jtfbGAm4LoA@mail.gmail.com>
User-Agent: Roundcube Webmail/1.4.11
Message-ID: <d81f73616aa5164a68033bc96662dfbc@oss.nttdata.com>
Archived-At: <https://www.postgresql.org/message-id/d81f73616aa5164a68033bc96662dfbc%40oss.nttdata.com>
Precedence: bulk

On 2023-06-15 01:48, James Coleman wrote:
> On Tue, Jun 13, 2023 at 11:53 AM James Coleman <jtc331@gmail.com> 
> wrote:
>> 
>> ...
>> I'm going to re-run tests with my patch version + resetting the flag
>> on SIGINT (and any other error condition) to be certain that the issue
>> you uncovered (where backends get stuck after a SIGINT not responding
>> to the requested plan logging) wasn't masking any other issues.
>> 
>> As long as that run is clean also then I believe the patch is safe
>> as-is even without the re-entrancy guard.
>> 
>> I'll report back with the results of that testing.
> 
> The tests have been running since last night, but have been apparently
> hung now for many hours. I haven't been able to fully look into it,
> but so far I know the hung (100% CPU) backend last logged this:
> 
> 2023-06-14 02:00:30.045 UTC client backend[84461]
> pg_regress/updatable_views LOG:  query plan running on backend with
> PID 84461 is:
>         Query Text: SELECT table_name, column_name, is_updatable
>           FROM information_schema.columns
>          WHERE table_name LIKE E'r_\\_view%'
>          ORDER BY table_name, ordinal_position;
> 
> The last output from the regression test harness was:
> 
> # parallel group (5 tests):  index_including create_view
> index_including_gist create_index create_index_spgist
> ok 66        + create_index                            36508 ms
> ok 67        + create_index_spgist                     38588 ms
> ok 68        + create_view                              1394 ms
> ok 69        + index_including                           654 ms
> ok 70        + index_including_gist                     1701 ms
> # parallel group (16 tests):  errors create_cast drop_if_exists
> create_aggregate roleattributes constraints hash_func typed_table
> infinite_recurse
> 
> Attaching gdb to the hung backend shows this:
> 
> #0  0x00005601ab1f9529 in ProcLockWakeup
> (lockMethodTable=lockMethodTable@entry=0x5601ab6484e0
> <default_lockmethod>, lock=lock@entry=0x7f5325c913f0) at proc.c:1655
> #1  0x00005601ab1e99dc in CleanUpLock (lock=lock@entry=0x7f5325c913f0,
> proclock=proclock@entry=0x7f5325d40d60,
> lockMethodTable=lockMethodTable@entry=0x5601ab6484e0
> <default_lockmethod>,
>     hashcode=hashcode@entry=573498161, wakeupNeeded=<optimized out>)
> at lock.c:1673
> #2  0x00005601ab1e9e21 in LockRefindAndRelease
> (lockMethodTable=lockMethodTable@entry=0x5601ab6484e0
> <default_lockmethod>, proc=<optimized out>,
> locktag=locktag@entry=0x5601ac3d7998, lockmode=lockmode@entry=1,
>     
> decrement_strong_lock_count=decrement_strong_lock_count@entry=false)
> at lock.c:3150
> #3  0x00005601ab1edb27 in LockReleaseAll
> (lockmethodid=lockmethodid@entry=1, allLocks=false) at lock.c:2295
> #4  0x00005601ab1f8599 in ProcReleaseLocks
> (isCommit=isCommit@entry=true) at proc.c:781
> #5  0x00005601ab37f1f4 in ResourceOwnerReleaseInternal
> (owner=<optimized out>, phase=phase@entry=RESOURCE_RELEASE_LOCKS,
> isCommit=isCommit@entry=true, isTopLevel=isTopLevel@entry=true) at
> resowner.c:618
> #6  0x00005601ab37f7b7 in ResourceOwnerRelease (owner=<optimized out>,
> phase=phase@entry=RESOURCE_RELEASE_LOCKS,
> isCommit=isCommit@entry=true, isTopLevel=isTopLevel@entry=true) at
> resowner.c:494
> #7  0x00005601aaec1d84 in CommitTransaction () at xact.c:2334
> #8  0x00005601aaec2b22 in CommitTransactionCommand () at xact.c:3067
> #9  0x00005601ab200a66 in finish_xact_command () at postgres.c:2783
> #10 0x00005601ab20338f in exec_simple_query (
>     query_string=query_string@entry=0x5601ac3b0858 "SELECT table_name,
> column_name, is_updatable\n  FROM information_schema.columns\n WHERE
> table_name LIKE E'r_\\\\_view%'\n ORDER BY table_name,
> ordinal_position;") at postgres.c:1300
> 
> I am unable to connect to the regression test Postgres instance --
> psql just hangs, so the lock seems to have affected the postmaster
> also.
> 
> I'm wondering if this might represent a bug in the current patch.

Thanks for running and analyzing the test!

Could you share me how you are running the test?

I imagined something like below, but currently couldn't reproduce it.
- apply both v26-0001 and v27-0002 and build
- run PostgreSQL with default GUCssaaa
- make installcheck-world
- run 'SELECT pg_log_query_plan(pid) FROM pg_stat_activity \watch 0.1' 
during make installcheck-world

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION