Re: RFC: Logging plan of the running query

On 2023-08-28 22:47, James Coleman wrote:
> On Mon, Aug 28, 2023 at 3:01 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-08-26 21:03, James Coleman wrote:
>> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
>> >>
>> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
>> >> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>> >> >
>> >> > On 2023-06-16 01:34, James Coleman wrote:
>> >> > > Attached is v28
>> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
>> >> > > when necessary. Once built with those two patches I'm simply running
>> >> > > `make check`.
>> >> >
>> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
>> >> > huge
>> >> > amount of memory and under some environments they were terminated by OOM
>> >> > killer.
>> >> >
>> >> > This was because memory was allocated from existing memory contexts and
>> >> > they
>> >> > were not freed after ProcessLogQueryPlanInterrupt().
>> >> > Updated the patch to use dedicated memory context for
>> >> > ProcessLogQueryPlanInterrupt().
>> >> >
>> >> > Applying attached patch and v28-0002 patch, `make check` successfully
>> >> > completed after 20min and 50GB of logs on my environment.
>> >> >
>> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
>> >> > >>> > The tests have been running since last night, but have been apparently
>> >> > >>> > hung now for many hours.
>> >> >
>> >> > I don't know if this has anything to do with the hung you faced, but I
>> >> > thought
>> >> > it might be possible that the large amount of memory usage resulted in
>> >> > swapping, which caused a significant delay in processing.
>> >>
>> >> Ah, yes, I think that could be a possible explanation. I was delaying
>> >> on this thread because I wasn't comfortable with having caused an
>> >> issue once (even if I couldn't easily reproduce) without at least some
>> >> theory as to the cause (and a fix).
>> >>
>> >> > If possible, I would be very grateful if you could try to reproduce this
>> >> > with
>> >> > the v29 patch.
>> >>
>> >> I'll kick off some testing.
>> >>
>> >
>> > I don't have time to investigate what's happening here, but 24 hours
>> > later the first "make check" is still running, and at first glance it
>> > seems to have the same behavior I'd seen that first time. The test
>> > output is to this point:
>> >
>> > # parallel group (5 tests): index_including create_view
>> > index_including_gist create_index create_index_spgist
>> > ok 66 + create_index 26365 ms
>> > ok 67 + create_index_spgist 27675 ms
>> > ok 68 + create_view 1235 ms
>> > ok 69 + index_including 1102 ms
>> > ok 70 + index_including_gist 1633 ms
>> > # parallel group (16 tests): create_aggregate create_cast errors
>> > roleattributes drop_if_exists hash_func typed_table create_am
>> > infinite_recurse
>> >
>> > and it hasn't progressed past that point since at least ~16 hours ago
>> > (the first several hours of the run I wasn't monitoring it).
>> >
>> > I haven't connected up gdb yet, and won't be able to until maybe
>> > tomorrow, but here's the ps output for postgres processes that are
>> > running:
>> >
>> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
>> > /home/admin/postgresql-test/bin/postgres -D
>> > /home/admin/postgresql-test-data
>> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
>> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
>> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
>> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
>> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
>> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
>> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
>> > --schedule=./parallel_schedule
>> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
>> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
>> > listen_addresses= -k /tmp/pg_regress-7mmGUa
>> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
>> > postgres: admin regression [local] VACUUM
>> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
>> > postgres: admin regression [local] DELETE waiting
>> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ALTER TABLE waiting
>> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ANALYZE waiting
>> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> >
>> > As you can see there are a bunch of backends presumably waiting, and
>> > also the VACUUM process has been pegging a single CPU core for at
>> > least since that ~16 hour ago mark.
>> >
>> > I hope to be able to do more investigation later, but I wanted to at
>> > least give you this information now.
>>
>> Thanks a lot for testing the patch!
>> I really appreciate your cooperation.
>>
>> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
>> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
>> below:
>>
>> ```
>> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
>> $ git apply
>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
>> $ ./configure --enable-debug --enable-cassert
>> $ make
>> $ make check
>>
>> ...(snip)...
>>
>> # parallel group (5 tests): index_including index_including_gist
>> create_view create_index create_index_spgist
>> ok 66 + create_index 25033 ms
>> ok 67 + create_index_spgist 26144 ms
>> ok 68 + create_view 3061 ms
>> ok 69 + index_including 976 ms
>> ok 70 + index_including_gist 2998 ms
>> # parallel group (16 tests): create_cast errors create_aggregate
>> roleattributes drop_if_exists hash_func typed_table
>> create_am select constraints updatable_views inherit triggers vacuum
>> create_function_sql infinite_recurse
>> ok 71 + create_aggregate 225 ms
>> ok 72 + create_function_sql 18874 ms
>> ok 73 + create_cast 168 ms
>>
>> ...(snip)...
>>
>> # All 215 tests passed.
>> ```
>>
>> If you notice any difference, I would be grateful if you could let me
>> know.
>
> 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..

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation