Fwd: Emit namespace in post-copy output

When running a VACUUM or CLUSTER command, the namespace name is not part of
the emitted message.

Using `vacuumdb` CLI tool recently with multiple jobs, I found that
reading the output messages harder to match the relations with their
namespaces.

Example:

INFO: vacuuming "sendgrid.open"
INFO: vacuuming "mailgun.open"
...
INFO: "open": found 0 removable, 31460776 nonremovable row versions in
1358656 pages
DETAIL: 0 dead row versions cannot be removed yet.
CPU 31.35s/261.26u sec elapsed 1620.68 sec.
...

In this example. the user can't readily tell which `open` relation was
completed.

Attached is a patch using existing functions to include the namespace in
the output string.

Looking forward to feedback!
-Mike Fiedler

On Tue, Jun 22, 2021 at 6:08 PM Mike <miketheman(at)gmail(dot)com> wrote:

> When running a VACUUM or CLUSTER command, the namespace name is not part
> of the emitted message.
>
> Using `vacuumdb` CLI tool recently with multiple jobs, I found that
> reading the output messages harder to match the relations with their
> namespaces.
>
> Example:
>
> INFO: vacuuming "sendgrid.open"
> INFO: vacuuming "mailgun.open"
> ...
> INFO: "open": found 0 removable, 31460776 nonremovable row versions in
> 1358656 pages
> DETAIL: 0 dead row versions cannot be removed yet.
> CPU 31.35s/261.26u sec elapsed 1620.68 sec.
> ...
>
> In this example. the user can't readily tell which `open` relation was
> completed.
>
> Attached is a patch using existing functions to include the namespace in
> the output string.
>
> Looking forward to feedback!
> -Mike Fiedler
>

I've added this to the open commitfest:
https://commitfest.postgresql.org/33/3200/

The change is quite simple, just 3 lines, adding the schema name to two
different lines of output.

As such, there is no obvious documentation to change, though I can imagine
that we have sample output from vacuum, vacuumdb or cluster somewhere that
would need to be updated.

I cobbled together a very simple test:

~/pgdata$ /usr/local/pgsql/bin/psql postgres
psql (14beta2)
Type "help" for help.
postgres=# create database mike_test;
CREATE DATABASE
postgres=# \c mike_test
You are now connected to database "mike_test" as user "corey".
mike_test=# create schema foo;
CREATE SCHEMA
mike_test=# create table foo.bar(x integer);
CREATE TABLE
mike_test=# \q
mike_test=# VACUUM FULL VERBOSE foo.bar;
INFO: vacuuming "foo.bar"
INFO: "foo.bar": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL: 0 dead row versions cannot be removed yet.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
VACUUM

And of course vacuumdb

~/pgdata$ /usr/local/pgsql/bin/vacuumdb --full --verbose mike_test
--table=foo.bar
vacuumdb: vacuuming database "mike_test"
INFO: vacuuming "foo.bar"
INFO: "foo.bar": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL: 0 dead row versions cannot be removed yet.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.

So far, so good.

Awesome, thanks! Are there any other steps I should take?

On Wed, Jun 23, 2021 at 5:46 PM Corey Huinker <corey(dot)huinker(at)gmail(dot)com>
wrote:

> On Tue, Jun 22, 2021 at 6:08 PM Mike <miketheman(at)gmail(dot)com> wrote:
>
>> When running a VACUUM or CLUSTER command, the namespace name is not part
>> of the emitted message.
>>
>> Using `vacuumdb` CLI tool recently with multiple jobs, I found that
>> reading the output messages harder to match the relations with their
>> namespaces.
>>
>> Example:
>>
>> INFO: vacuuming "sendgrid.open"
>> INFO: vacuuming "mailgun.open"
>> ...
>> INFO: "open": found 0 removable, 31460776 nonremovable row versions in
>> 1358656 pages
>> DETAIL: 0 dead row versions cannot be removed yet.
>> CPU 31.35s/261.26u sec elapsed 1620.68 sec.
>> ...
>>
>> In this example. the user can't readily tell which `open` relation was
>> completed.
>>
>> Attached is a patch using existing functions to include the namespace in
>> the output string.
>>
>> Looking forward to feedback!
>> -Mike Fiedler
>>
>
> I've added this to the open commitfest:
> https://commitfest.postgresql.org/33/3200/
>
> The change is quite simple, just 3 lines, adding the schema name to two
> different lines of output.
>
> As such, there is no obvious documentation to change, though I can imagine
> that we have sample output from vacuum, vacuumdb or cluster somewhere that
> would need to be updated.
>
> I cobbled together a very simple test:
>
> ~/pgdata$ /usr/local/pgsql/bin/psql postgres
> psql (14beta2)
> Type "help" for help.
> postgres=# create database mike_test;
> CREATE DATABASE
> postgres=# \c mike_test
> You are now connected to database "mike_test" as user "corey".
> mike_test=# create schema foo;
> CREATE SCHEMA
> mike_test=# create table foo.bar(x integer);
> CREATE TABLE
> mike_test=# \q
> mike_test=# VACUUM FULL VERBOSE foo.bar;
> INFO: vacuuming "foo.bar"
> INFO: "foo.bar": found 0 removable, 0 nonremovable row versions in 0 pages
> DETAIL: 0 dead row versions cannot be removed yet.
> CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
> VACUUM
>
>
> And of course vacuumdb
>
> ~/pgdata$ /usr/local/pgsql/bin/vacuumdb --full --verbose mike_test
> --table=foo.bar
> vacuumdb: vacuuming database "mike_test"
> INFO: vacuuming "foo.bar"
> INFO: "foo.bar": found 0 removable, 0 nonremovable row versions in 0 pages
> DETAIL: 0 dead row versions cannot be removed yet.
> CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
>
>
> So far, so good.
>

On Fri, Jun 25, 2021, at 12:10 PM, Mike wrote:
> Awesome, thanks! Are there any other steps I should take?
No. Keep an eye on this thread. If you modify this patch, check if PostgreSQL
Patch Tester [1] reports failure. Since your patch does not modify a
considerable amount of code, it probably won't conflict with another patch. If
so, a reviewer will say so. If your patch doesn't have objections, it will
eventually be committed. BTW, your patch looks good to me.

[1] http://cfbot.cputube.org/index.html

--
Euler Taveira
EDB https://www.enterprisedb.com/

The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: not tested
Documentation: not tested

Passed make check-world. Running make installcheck-world had 2 errors out of 209, but I got those same 2 errors on a clean branch.

Feature is as-described, and very simple.

As far as I can tell, there is no external specification for vacuum or any related utility.

I searched the documentation, and found several examples of the invocation of the VACUUM FULL command and vacuuumdb utility, but at no point was sample output shown, so this change will not require updating documentation.

The new status of this patch is: Ready for Committer

I took a look at this I agree with the reviewer that it's a good change. The
output from multiple jobs in vacuumdb is clearly easier to parse with this
since the initial LOG and later DETAIL can be interleaved with other relations
of the same name in other namespaces.

+ get_namespace_name(RelationGetNamespace(OldHeap)),

Since get_namespace_name() returns a palloced string, this will lead to a 2x
leak of the namespace length as opposed to the 1x of today. While hardly a big
deal, it seems prudent to cap this by storing the returned string locally now
that we need it twice.

I've updated the patch with this, see the attached v2. Barring objections I
will go ahead with this.

--
Daniel Gustafsson https://vmware.com/

On Wed, Jul 28, 2021 at 04:15:19PM +0200, Daniel Gustafsson wrote:
> Since get_namespace_name() returns a palloced string, this will lead to a 2x
> leak of the namespace length as opposed to the 1x of today. While hardly a big
> deal, it seems prudent to cap this by storing the returned string locally now
> that we need it twice.

I don't think this matters much. A quick read of the code shows that
this memory should be allocated within the transaction context running
CLUSTER/VACUUM FULL, and that gets free'd in the internal calls of
CommitTransactionCommand().
--
Michael

> On 28 Jul 2021, at 16:15, Daniel Gustafsson <daniel(at)yesql(dot)se> wrote:

> I took a look at this I agree with the reviewer that it's a good change.

Pushed to master, thanks!

--
Daniel Gustafsson https://vmware.com/