Re: RFC: Logging plan of the running query - Mailing list pgsql-hackers

On 2023-08-26 21:03, James Coleman wrote:
> On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331@gmail.com> wrote:
>> 
>> On Thu, Aug 17, 2023 at 10:02 AM torikoshia 
>> <torikoshia@oss.nttdata.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.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation