Thread: [HACKERS] Additional logging for VACUUM and ANALYZE

Hi hackers,

Presently, there are a few edge cases in vacuum_rel() and analyze_rel() that I
believe do not have sufficient logging.  This was discussed a bit in the
vacuum-multiple-relations thread [0], but it was ultimately decided that any
logging changes should be proposed separately.

There are two cases that my proposed patch handles:

    1) If VACOPT_NOWAIT is specified, the relation will be skipped if we
       cannot obtain a lock on the relation without waiting.  This option
       is currently only used for autovacuum, and there is a corresponding
       log message that is only emitted for autovacuum as well.  IMO this
       code is operating on a pretty volatile assumption, as I can see a
       potential use-case for allowing customers to specify VACOPT_NOWAIT.
       For example, a nightly manual VACUUM command might benefit from
       this option by skipping tables that autovacuum is already working
       on or that otherwise cannot be immediately locked.  However, I am
       not proposing to give customers this option in manual VACUUM/ANALYZE
       commands here, just that the logging logic need not assume
       differently.

    2) If a relation is dropped between the time vacuum() looks it up and
       when it is processed, it will currently be silently skipped.  This
       seems prone to cause confusion when a relation does not appear
       in the VERBOSE output of VACUUM/ANALYZE or in the autovacuum logs.
       It is arguable that we should not emit a message for relations that
       were not explicitly specified (e.g. VACUUM with no tables
       specified), and I am inclined to agree.  Fortunately, the recent
       vacuum-multiple-relations change avoids populating the relation's
       RangeVar if it was not listed in the command, which makes it trivial
       to decide whether to log.

So, the attached patch changes the existing lock contention message to be
emitted for non-autovacuum sessions if necessary, and it adds a "skipping"
message when a specified relation disappears before it is processed.  For
consistency, autovacuum logs are emitted at LOG, and logs for manual commands
are emitted at WARNING.  This patch also includes a minor documentation change
and a test that exercises a bit of this functionality.

If this change were to be considered for back-patching, we would likely want to
also apply Michael's RangeVar fix for partitioned tables to 10 [1].  Without
this change, log messages for unspecified partitions will be emitted with the
parent's RangeVar information.

Nathan

[0] https://postgr.es/m/E061A8E3-5E3D-494D-94F0-E8A9B312BBFC@amazon.com
[1] https://postgr.es/m/CAB7nPqRX1465FP%2Bameysxxt63tCQDDW6KvaTPMfkSxaT1TFGfw%40mail.gmail.com


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Thu, Oct 5, 2017 at 1:23 AM, Bossart, Nathan <bossartn@amazon.com> wrote:
> Presently, there are a few edge cases in vacuum_rel() and analyze_rel() that I
> believe do not have sufficient logging.  This was discussed a bit in the
> vacuum-multiple-relations thread [0], but it was ultimately decided that any
> logging changes should be proposed separately.

I think that I agree with that, especially now with VACUUM allowing
multiple relations. The discussion then would be how much logging we
want. WARNING looks adapted per the discussions we had on the other
thread as manual VACUUMs can now involve much more relations, even
with partitioned tables. More opinions would be welcome.

> So, the attached patch changes the existing lock contention message to be
> emitted for non-autovacuum sessions if necessary, and it adds a "skipping"
> message when a specified relation disappears before it is processed.  For
> consistency, autovacuum logs are emitted at LOG, and logs for manual commands
> are emitted at WARNING.  This patch also includes a minor documentation change

This is here:        250ms or longer will be logged.  In addition, when this parameter is        set to any value other
than<literal>-1</literal>, a message will be
 
-        logged if an autovacuum action is skipped due to the existence of a
-        conflicting lock.  Enabling this parameter can be helpful
+        logged if an autovacuum action is skipped due to a
conflicting lock or a
+        concurrently dropped relation.  Enabling this parameter can be helpful        in tracking autovacuum activity.
This parameter can only be set in
 
So that looks adapted to the patch.

> and a test that exercises a bit of this functionality.

My take on those test would be to not include them. This is a lot just
to test two logging lines where the relation has been dropped.

> If this change were to be considered for back-patching, we would likely want to
> also apply Michael's RangeVar fix for partitioned tables to 10 [1].  Without
> this change, log messages for unspecified partitions will be emitted with the
> parent's RangeVar information.

Well, that's assuming that we begin logging some information for
manual VACUUMs using the specified RangeVar, something that does not
happen at the top of upstream REL_10_STABLE, but can happen if we were
to include the patch you are proposing on this thread for
REL_10_STABLE. But the latter is not going to happen. Or did you patch
your version of v10 to do so in your stuff? For v10 the ship has
already sailed, so I think that it would be better to just let it go,
and rely on v11 which has added all the facility we wanted.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 10/5/17, 12:29 AM, "Michael Paquier" <michael.paquier@gmail.com> wrote:
> On Thu, Oct 5, 2017 at 1:23 AM, Bossart, Nathan <bossartn@amazon.com> wrote:
>> Presently, there are a few edge cases in vacuum_rel() and analyze_rel() that I
>> believe do not have sufficient logging.  This was discussed a bit in the
>> vacuum-multiple-relations thread [0], but it was ultimately decided that any
>> logging changes should be proposed separately.
>
> I think that I agree with that, especially now with VACUUM allowing
> multiple relations. The discussion then would be how much logging we
> want. WARNING looks adapted per the discussions we had on the other
> thread as manual VACUUMs can now involve much more relations, even
> with partitioned tables. More opinions would be welcome.

Thanks for taking a look.

>> and a test that exercises a bit of this functionality.
>
> My take on those test would be to not include them. This is a lot just
> to test two logging lines where the relation has been dropped.

Yeah, I'm not terribly concerned about those tests.

>> If this change were to be considered for back-patching, we would likely want to
>> also apply Michael's RangeVar fix for partitioned tables to 10 [1].  Without
>> this change, log messages for unspecified partitions will be emitted with the
>> parent's RangeVar information.
>
> Well, that's assuming that we begin logging some information for
> manual VACUUMs using the specified RangeVar, something that does not
> happen at the top of upstream REL_10_STABLE, but can happen if we were
> to include the patch you are proposing on this thread for
> REL_10_STABLE. But the latter is not going to happen. Or did you patch
> your version of v10 to do so in your stuff? For v10 the ship has
> already sailed, so I think that it would be better to just let it go,
> and rely on v11 which has added all the facility we wanted.

I agree.  I didn't mean to suggest that it should be back-patched, just
that v10 has a small quirk that needs to be handled if others feel
differently.

Nathan


--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 10/5/17, 12:29 AM, "Michael Paquier" <michael.paquier@gmail.com> wrote:
>> and a test that exercises a bit of this functionality.
>
> My take on those test would be to not include them. This is a lot just
> to test two logging lines where the relation has been dropped.

Here is a new version of the patch without the tests.

Nathan


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

The patch doesn't apply against master anymore:

fabrizio@macanudo:/d/postgresql (master) 
$ git apply /tmp/new_vacuum_log_messages_v2.patch
error: patch failed: doc/src/sgml/config.sgml:5899
error: doc/src/sgml/config.sgml: patch does not apply

Regards,

Fabrízio Mello

The new status of this patch is: Waiting on Author

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 11/7/17, 7:36 AM, "Fabrízio Mello" <fabriziomello@gmail.com> wrote:
> The patch doesn't apply against master anymore:

Thanks for the review.  Here is a rebased version of the patch.

Nathan


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

>     int         save_nestlevel;
> +   bool            rel_lock;
> 

Just remove the additional tab indentation before rel_lock variable. 

The rest looks good to me.

Regards,

Fabrízio Mello


The new status of this patch is: Waiting on Author

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 11/7/17, 9:13 AM, "Fabrízio Mello" <fabriziomello@gmail.com> wrote:
>>     int         save_nestlevel;
>> +   bool            rel_lock;
>> 
>
> Just remove the additional tab indentation before rel_lock variable. 

I've removed the extra tab in v4.

Nathan


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Thu, Nov 30, 2017 at 10:04 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:
> On Wed, Nov 8, 2017 at 12:54 AM, Fabrízio de Royes Mello
> <fabriziomello@gmail.com> wrote:
>> Great. Changed status to ready for commiter.
>
> The patch still applies, but no committer seem to be interested in the
> topic, so moved to next CF.

The general idea of this patch seems OK to me.

+    rel_lock = true;

I think it would look nicer to initialize this when you declare the
variable, instead of having a separate line of code for that purpose.

+        if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+            elevel = LOG;
+        else if (!IsAutoVacuumWorkerProcess())
+            elevel = WARNING;
+        else
+            return;

This can be rewritten with only one call to
IsAutoVacuumWorkerProcess() by reversing the order of the branches.

+            PopActiveSnapshot();
+            CommitTransactionCommand();
+            return false;

vacuum_rel already has too many copies of this logic -- can we try to
avoid duplicating it into two more places?  It seems like you could
easily do that like this:

int elevel = 0;
if (relation != NULL)
{
/* maybe set elevel */
}
if (elevel != 0)
{
if (!rel_lock)
   /* emit message */
else
   /* emit other message */
}

This wouldn't be the first bit of code to assume that elevel == 0 can
be used as a sentinel value meaning "none", so I think it's OK to do
that.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 12/1/17, 7:34 AM, "Robert Haas" <robertmhaas@gmail.com> wrote:
> The general idea of this patch seems OK to me.

Thanks for the review, Robert.  I've attached a new version that
addresses your feedback.

> +    rel_lock = true;
>
> I think it would look nicer to initialize this when you declare the
> variable, instead of having a separate line of code for that purpose.

Sure, that seems fine to me.

> +        if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
> +            elevel = LOG;
> +        else if (!IsAutoVacuumWorkerProcess())
> +            elevel = WARNING;
> +        else
> +            return;
>
> This can be rewritten with only one call to
> IsAutoVacuumWorkerProcess() by reversing the order of the branches.

Yes, good catch.

> +            PopActiveSnapshot();
> +            CommitTransactionCommand();
> +            return false;
>
> vacuum_rel already has too many copies of this logic -- can we try to
> avoid duplicating it into two more places?  It seems like you could
> easily do that like this:
>
> int elevel = 0;
> if (relation != NULL)
> {
> /* maybe set elevel */
> }
> if (elevel != 0)
> {
> if (!rel_lock)
>    /* emit message */
> else
>    /* emit other message */
> }
>
> This wouldn't be the first bit of code to assume that elevel == 0 can
> be used as a sentinel value meaning "none", so I think it's OK to do
> that.

Sure.  This is how I originally put it together, but I wasn't
sure if setting elevel to 0 was a sanctioned approach.

Nathan

On Fri, Dec 1, 2017 at 11:29 AM, Bossart, Nathan <bossartn@amazon.com> wrote:
> Thanks for the review, Robert.  I've attached a new version that
> addresses your feedback.

Thanks.  I think this looks fine now, except that (1) it needs a
pgindent run and (2) I vote for putting the test case back.  Michael
thought the test case was too much because this is so obscure, but I
think that's exactly why it needs a test case.  Otherwise, somebody a
few years from now may not even be able to figure out how to hit this
message, and if it gets broken, we won't know.  This code seems to be
fairly easy to break in subtle ways, so I think more test coverage is
good.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 12/1/17, 2:03 PM, "Robert Haas" <robertmhaas@gmail.com> wrote:
> Thanks.  I think this looks fine now, except that (1) it needs a
> pgindent run and (2) I vote for putting the test case back.  Michael
> thought the test case was too much because this is so obscure, but I
> think that's exactly why it needs a test case.  Otherwise, somebody a
> few years from now may not even be able to figure out how to hit this
> message, and if it gets broken, we won't know.  This code seems to be
> fairly easy to break in subtle ways, so I think more test coverage is
> good.

Makes sense.  I ran pgindent and re-added the test case for v6 of the
patch.

Nathan

On Fri, Dec 1, 2017 at 4:05 PM, Bossart, Nathan <bossartn@amazon.com> wrote:
> On 12/1/17, 2:03 PM, "Robert Haas" <robertmhaas@gmail.com> wrote:
>> Thanks.  I think this looks fine now, except that (1) it needs a
>> pgindent run and (2) I vote for putting the test case back.  Michael
>> thought the test case was too much because this is so obscure, but I
>> think that's exactly why it needs a test case.  Otherwise, somebody a
>> few years from now may not even be able to figure out how to hit this
>> message, and if it gets broken, we won't know.  This code seems to be
>> fairly easy to break in subtle ways, so I think more test coverage is
>> good.
>
> Makes sense.  I ran pgindent and re-added the test case for v6 of the
> patch.

Committed.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 12/4/17, 2:27 PM, "Robert Haas" <robertmhaas@gmail.com> wrote:
> Committed.

Thanks!

Nathan