Additional logging for VACUUM and ANALYZE

Started by Bossart, Nathanover 8 years ago16 messages
#1Bossart, Nathan
bossartn@amazon.com
1 attachment(s)

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]/messages/by-id/E061A8E3-5E3D-494D-94F0-E8A9B312BBFC@amazon.com, 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]/messages/by-id/CAB7nPqRX1465FP+ameysxxt63tCQDDW6KvaTPMfkSxaT1TFGfw@mail.gmail.com. Without
this change, log messages for unspecified partitions will be emitted with the
parent's RangeVar information.

Nathan

[0]: /messages/by-id/E061A8E3-5E3D-494D-94F0-E8A9B312BBFC@amazon.com
[1]: /messages/by-id/CAB7nPqRX1465FP+ameysxxt63tCQDDW6KvaTPMfkSxaT1TFGfw@mail.gmail.com

Attachments:

new_vacuum_log_messages_v1.patchapplication/octet-stream; name=new_vacuum_log_messages_v1.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c13f602..caaae67 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5879,8 +5879,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index d432f82..9e5c403 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -142,6 +143,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	 * matter if we ever try to accumulate stats on dead tuples.) If the rel
 	 * has been dropped since we last saw it, we don't need to process it.
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, ShareUpdateExclusiveLock);
 	else if (ConditionalLockRelationOid(relid, ShareUpdateExclusiveLock))
@@ -149,15 +151,51 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that analyze_rel's caller has intentionally not
+		 * provided this information so that this logging is skipped,
+		 * anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * ANALYZE, we emit a WARNING to match the log statements in
+		 * the permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index f439b55..96bcb0b 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1327,6 +1327,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool			rel_lock;
 
 	Assert(params != NULL);
 
@@ -1390,6 +1391,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	 * If we've been asked not to wait for the relation lock, acquire it first
 	 * in non-blocking mode, before calling try_relation_open().
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, lmode);
 	else if (ConditionalLockRelationOid(relid, lmode))
@@ -1397,16 +1399,58 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int elevel;
+
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that vacuum_rel's caller has intentionally not provided
+		 * this information so that this logging is skipped, anyway.
+		 */
+		if (relation == NULL)
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * VACUUM, we emit a WARNING to match the log statements in the
+		 * permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		if (!rel_lock)
+			ereport(elevel,
+					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+					 errmsg("skipping vacuum of \"%s\" --- lock not available",
+							relation->relname)));
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
diff --git a/src/test/isolation/expected/vacuum-concurrent-drop.out b/src/test/isolation/expected/vacuum-concurrent-drop.out
new file mode 100644
index 0000000..72d80a1
--- /dev/null
+++ b/src/test/isolation/expected/vacuum-concurrent-drop.out
@@ -0,0 +1,76 @@
+Parsed test spec with 2 sessions
+
+starting permutation: lock vac_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_specified: VACUUM test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping vacuum of "test2" --- relation no longer exists
+step vac_specified: <... completed>
+
+starting permutation: lock vac_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_all: VACUUM; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step vac_all: <... completed>
+
+starting permutation: lock analyze_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step analyze_specified: ANALYZE test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping analyze of "test2" --- relation no longer exists
+step analyze_specified: <... completed>
+
+starting permutation: lock analyze_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step analyze_all: ANALYZE; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step analyze_all: <... completed>
+
+starting permutation: lock vac_analyze_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_analyze_specified: VACUUM ANALYZE test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping vacuum of "test2" --- relation no longer exists
+step vac_analyze_specified: <... completed>
+
+starting permutation: lock vac_analyze_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_analyze_all: VACUUM ANALYZE; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step vac_analyze_all: <... completed>
diff --git a/src/test/isolation/isolation_schedule b/src/test/isolation/isolation_schedule
index 7dad3c2..eb566eb 100644
--- a/src/test/isolation/isolation_schedule
+++ b/src/test/isolation/isolation_schedule
@@ -63,3 +63,4 @@ test: sequence-ddl
 test: async-notify
 test: vacuum-reltuples
 test: timeouts
+test: vacuum-concurrent-drop
diff --git a/src/test/isolation/specs/vacuum-concurrent-drop.spec b/src/test/isolation/specs/vacuum-concurrent-drop.spec
new file mode 100644
index 0000000..31fc161
--- /dev/null
+++ b/src/test/isolation/specs/vacuum-concurrent-drop.spec
@@ -0,0 +1,45 @@
+# Test for log messages emitted by VACUUM and ANALYZE when a specified
+# relation is concurrently dropped.
+#
+# This also verifies that log messages are not emitted for concurrently
+# dropped relations that were not specified in the VACUUM or ANALYZE
+# command.
+
+setup
+{
+	CREATE TABLE test1 (a INT);
+	CREATE TABLE test2 (a INT);
+}
+
+teardown
+{
+	DROP TABLE IF EXISTS test1;
+	DROP TABLE IF EXISTS test2;
+}
+
+session "s1"
+step "lock"
+{
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+}
+step "drop_and_commit"
+{
+	DROP TABLE test2;
+	COMMIT;
+}
+
+session "s2"
+step "vac_specified"		{ VACUUM test1, test2; }
+step "vac_all"			{ VACUUM; }
+step "analyze_specified"	{ ANALYZE test1, test2; }
+step "analyze_all"		{ ANALYZE; }
+step "vac_analyze_specified"	{ VACUUM ANALYZE test1, test2; }
+step "vac_analyze_all"		{ VACUUM ANALYZE; }
+
+permutation "lock" "vac_specified" "drop_and_commit"
+permutation "lock" "vac_all" "drop_and_commit"
+permutation "lock" "analyze_specified" "drop_and_commit"
+permutation "lock" "analyze_all" "drop_and_commit"
+permutation "lock" "vac_analyze_specified" "drop_and_commit"
+permutation "lock" "vac_analyze_all" "drop_and_commit"
#2Michael Paquier
michael.paquier@gmail.com
In reply to: Bossart, Nathan (#1)
Re: Additional logging for VACUUM and ANALYZE

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

#3Bossart, Nathan
bossartn@amazon.com
In reply to: Michael Paquier (#2)
Re: Additional logging for VACUUM and ANALYZE

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

#4Bossart, Nathan
bossartn@amazon.com
In reply to: Bossart, Nathan (#3)
1 attachment(s)
Re: Additional logging for VACUUM and ANALYZE

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

Attachments:

new_vacuum_log_messages_v2.patchapplication/octet-stream; name=new_vacuum_log_messages_v2.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index b012a26..4893f15 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5899,8 +5899,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 760d191..214b486 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -142,6 +143,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	 * matter if we ever try to accumulate stats on dead tuples.) If the rel
 	 * has been dropped since we last saw it, we don't need to process it.
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, ShareUpdateExclusiveLock);
 	else if (ConditionalLockRelationOid(relid, ShareUpdateExclusiveLock))
@@ -149,15 +151,51 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that analyze_rel's caller has intentionally not
+		 * provided this information so that this logging is skipped,
+		 * anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * ANALYZE, we emit a WARNING to match the log statements in
+		 * the permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index cbd6e9b..2ba3d7d 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1330,6 +1330,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool			rel_lock;
 
 	Assert(params != NULL);
 
@@ -1393,6 +1394,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	 * If we've been asked not to wait for the relation lock, acquire it first
 	 * in non-blocking mode, before calling try_relation_open().
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, lmode);
 	else if (ConditionalLockRelationOid(relid, lmode))
@@ -1400,16 +1402,58 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int elevel;
+
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that vacuum_rel's caller has intentionally not provided
+		 * this information so that this logging is skipped, anyway.
+		 */
+		if (relation == NULL)
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * VACUUM, we emit a WARNING to match the log statements in the
+		 * permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		if (!rel_lock)
+			ereport(elevel,
+					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+					 errmsg("skipping vacuum of \"%s\" --- lock not available",
+							relation->relname)));
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
#5Fabrízio Mello
fabriziomello@gmail.com
In reply to: Bossart, Nathan (#4)
Re: Additional logging for VACUUM and ANALYZE

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

#6Bossart, Nathan
bossartn@amazon.com
In reply to: Fabrízio Mello (#5)
1 attachment(s)
Re: Additional logging for VACUUM and ANALYZE

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

Attachments:

new_vacuum_log_messages_v3.patchapplication/octet-stream; name=new_vacuum_log_messages_v3.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d360fc4..d265be9 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5899,8 +5899,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</filename> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 760d191..214b486 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -142,6 +143,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	 * matter if we ever try to accumulate stats on dead tuples.) If the rel
 	 * has been dropped since we last saw it, we don't need to process it.
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, ShareUpdateExclusiveLock);
 	else if (ConditionalLockRelationOid(relid, ShareUpdateExclusiveLock))
@@ -149,15 +151,51 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that analyze_rel's caller has intentionally not
+		 * provided this information so that this logging is skipped,
+		 * anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * ANALYZE, we emit a WARNING to match the log statements in
+		 * the permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index cbd6e9b..2ba3d7d 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1330,6 +1330,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool			rel_lock;
 
 	Assert(params != NULL);
 
@@ -1393,6 +1394,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	 * If we've been asked not to wait for the relation lock, acquire it first
 	 * in non-blocking mode, before calling try_relation_open().
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, lmode);
 	else if (ConditionalLockRelationOid(relid, lmode))
@@ -1400,16 +1402,58 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int elevel;
+
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that vacuum_rel's caller has intentionally not provided
+		 * this information so that this logging is skipped, anyway.
+		 */
+		if (relation == NULL)
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * VACUUM, we emit a WARNING to match the log statements in the
+		 * permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		if (!rel_lock)
+			ereport(elevel,
+					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+					 errmsg("skipping vacuum of \"%s\" --- lock not available",
+							relation->relname)));
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
#7Fabrízio Mello
fabriziomello@gmail.com
In reply to: Bossart, Nathan (#6)
Re: Additional logging for VACUUM and ANALYZE

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

#8Bossart, Nathan
bossartn@amazon.com
In reply to: Fabrízio Mello (#7)
1 attachment(s)
Re: Additional logging for VACUUM and ANALYZE

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

Attachments:

new_vacuum_log_messages_v4.patchapplication/octet-stream; name=new_vacuum_log_messages_v4.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d360fc4..d265be9 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5899,8 +5899,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</filename> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 760d191..214b486 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -142,6 +143,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	 * matter if we ever try to accumulate stats on dead tuples.) If the rel
 	 * has been dropped since we last saw it, we don't need to process it.
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, ShareUpdateExclusiveLock);
 	else if (ConditionalLockRelationOid(relid, ShareUpdateExclusiveLock))
@@ -149,15 +151,51 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that analyze_rel's caller has intentionally not
+		 * provided this information so that this logging is skipped,
+		 * anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * ANALYZE, we emit a WARNING to match the log statements in
+		 * the permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index cbd6e9b..4fa2300 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1330,6 +1330,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool		rel_lock;
 
 	Assert(params != NULL);
 
@@ -1393,6 +1394,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	 * If we've been asked not to wait for the relation lock, acquire it first
 	 * in non-blocking mode, before calling try_relation_open().
 	 */
+	rel_lock = true;
 	if (!(options & VACOPT_NOWAIT))
 		onerel = try_relation_open(relid, lmode);
 	else if (ConditionalLockRelationOid(relid, lmode))
@@ -1400,16 +1402,58 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int elevel;
+
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that vacuum_rel's caller has intentionally not provided
+		 * this information so that this logging is skipped, anyway.
+		 */
+		if (relation == NULL)
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * VACUUM, we emit a WARNING to match the log statements in the
+		 * permissions checks.
+		 */
+		if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+			elevel = LOG;
+		else if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else
+		{
+			PopActiveSnapshot();
+			CommitTransactionCommand();
+			return false;
+		}
+
+		if (!rel_lock)
+			ereport(elevel,
+					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+					 errmsg("skipping vacuum of \"%s\" --- lock not available",
+							relation->relname)));
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
#9Fabrízio de Royes Mello
fabriziomello@gmail.com
In reply to: Bossart, Nathan (#8)
Re: Additional logging for VACUUM and ANALYZE

On Tue, Nov 7, 2017 at 1:35 PM, Bossart, Nathan <bossartn@amazon.com> wrote:

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.

Great. Changed status to ready for commiter.

Regards,

--
Fabrízio de Royes Mello
Consultoria/Coaching PostgreSQL

Show quoted text

Timbira: http://www.timbira.com.br
Blog: http://fabriziomello.github.io
Linkedin: http://br.linkedin.com/in/fabriziomello
Twitter: http://twitter.com/fabriziomello
Github: http://github.com/fabriziomello

#10Michael Paquier
michael.paquier@gmail.com
In reply to: Fabrízio de Royes Mello (#9)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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.
--
Michael

#11Robert Haas
robertmhaas@gmail.com
In reply to: Michael Paquier (#10)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

#12Bossart, Nathan
bossartn@amazon.com
In reply to: Robert Haas (#11)
1 attachment(s)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

Attachments:

new_vacuum_log_messages_v5.patchapplication/octet-stream; name=new_vacuum_log_messages_v5.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 3060597..563ad1f 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5926,8 +5926,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</filename> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 760d191..f758025 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock = true;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -149,15 +150,51 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that analyze_rel's caller has intentionally not
+		 * provided this information so that this logging is skipped,
+		 * anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG
+		 * if log_autovacuum_min_duration is not disabled.  For manual
+		 * ANALYZE, we emit a WARNING to match the log statements in
+		 * the permissions checks.
+		 */
+		if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else if (params->log_min_duration >= 0)
+			elevel = LOG;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index cbd6e9b..686a366 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1330,6 +1330,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool		rel_lock = true;
 
 	Assert(params != NULL);
 
@@ -1400,16 +1401,52 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int elevel = 0;
+
+		/*
+		 * Determine the log level.
+		 *
+		 * If the RangeVar is not defined, we do not have enough
+		 * information to provide a meaningful log statement.  Chances
+		 * are that vacuum_rel's caller has intentionally not provided
+		 * this information so that this logging is skipped, anyway.
+		 *
+		 * Otherwise, for autovacuum logs, we emit a LOG if
+		 * log_autovacuum_min_duration is not disabled.  For manual
+		 * VACUUM, we emit a WARNING to match the log statements in the
+		 * permission checks.
+		 */
+		if (relation != NULL)
+		{
+			if (!IsAutoVacuumWorkerProcess())
+				elevel = WARNING;
+			else if (params->log_min_duration >= 0)
+				elevel = LOG;
+		}
+
+		if (elevel != 0)
+		{
+			if (!rel_lock)
+				ereport(elevel,
+						(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+						 errmsg("skipping vacuum of \"%s\" --- lock not available",
+								relation->relname)));
+			else
+				ereport(elevel,
+						(errcode(ERRCODE_UNDEFINED_TABLE),
+						 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+								relation->relname)));
+		}
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
#13Robert Haas
robertmhaas@gmail.com
In reply to: Bossart, Nathan (#12)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

#14Bossart, Nathan
bossartn@amazon.com
In reply to: Robert Haas (#13)
1 attachment(s)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

Attachments:

new_vacuum_log_messages_v6.patchapplication/octet-stream; name=new_vacuum_log_messages_v6.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 3060597..563ad1f 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5926,8 +5926,8 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
         <literal>250ms</literal> then all automatic vacuums and analyzes that run
         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
         the <filename>postgresql.conf</filename> file or on the server command line;
         but the setting can be overridden for individual tables by
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 760d191..f952b3c 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -120,6 +120,7 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	int			elevel;
 	AcquireSampleRowsFunc acquirefunc = NULL;
 	BlockNumber relpages = 0;
+	bool		rel_lock = true;
 
 	/* Select logging level */
 	if (options & VACOPT_VERBOSE)
@@ -149,15 +150,50 @@ analyze_rel(Oid relid, RangeVar *relation, int options,
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
+		rel_lock = false;
+	}
+
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
+	if (!onerel)
+	{
+		/*
+		 * If the RangeVar is not defined, we do not have enough information
+		 * to provide a meaningful log statement.  Chances are that
+		 * analyze_rel's caller has intentionally not provided this
+		 * information so that this logging is skipped, anyway.
+		 */
+		if (relation == NULL)
+			return;
+
+		/*
+		 * Determine the log level.  For autovacuum logs, we emit a LOG if
+		 * log_autovacuum_min_duration is not disabled.  For manual ANALYZE,
+		 * we emit a WARNING to match the log statements in the permissions
+		 * checks.
+		 */
+		if (!IsAutoVacuumWorkerProcess())
+			elevel = WARNING;
+		else if (params->log_min_duration >= 0)
+			elevel = LOG;
+		else
+			return;
+
+		if (!rel_lock)
+			ereport(elevel,
 					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
 					 errmsg("skipping analyze of \"%s\" --- lock not available",
 							relation->relname)));
-	}
-	if (!onerel)
+		else
+			ereport(elevel,
+					(errcode(ERRCODE_UNDEFINED_TABLE),
+					 errmsg("skipping analyze of \"%s\" --- relation no longer exists",
+							relation->relname)));
+
 		return;
+	}
 
 	/*
 	 * Check permissions --- this should match vacuum's check!
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index cbd6e9b..4abe6b1 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -1330,6 +1330,7 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	Oid			save_userid;
 	int			save_sec_context;
 	int			save_nestlevel;
+	bool		rel_lock = true;
 
 	Assert(params != NULL);
 
@@ -1400,16 +1401,52 @@ vacuum_rel(Oid relid, RangeVar *relation, int options, VacuumParams *params)
 	else
 	{
 		onerel = NULL;
-		if (relation &&
-			IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
-			ereport(LOG,
-					(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
-					 errmsg("skipping vacuum of \"%s\" --- lock not available",
-							relation->relname)));
+		rel_lock = false;
 	}
 
+	/*
+	 * If we failed to open or lock the relation, emit a log message before
+	 * exiting.
+	 */
 	if (!onerel)
 	{
+		int			elevel = 0;
+
+		/*
+		 * Determine the log level.
+		 *
+		 * If the RangeVar is not defined, we do not have enough information
+		 * to provide a meaningful log statement.  Chances are that
+		 * vacuum_rel's caller has intentionally not provided this information
+		 * so that this logging is skipped, anyway.
+		 *
+		 * Otherwise, for autovacuum logs, we emit a LOG if
+		 * log_autovacuum_min_duration is not disabled.  For manual VACUUM, we
+		 * emit a WARNING to match the log statements in the permission
+		 * checks.
+		 */
+		if (relation != NULL)
+		{
+			if (!IsAutoVacuumWorkerProcess())
+				elevel = WARNING;
+			else if (params->log_min_duration >= 0)
+				elevel = LOG;
+		}
+
+		if (elevel != 0)
+		{
+			if (!rel_lock)
+				ereport(elevel,
+						(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
+						 errmsg("skipping vacuum of \"%s\" --- lock not available",
+								relation->relname)));
+			else
+				ereport(elevel,
+						(errcode(ERRCODE_UNDEFINED_TABLE),
+						 errmsg("skipping vacuum of \"%s\" --- relation no longer exists",
+								relation->relname)));
+		}
+
 		PopActiveSnapshot();
 		CommitTransactionCommand();
 		return false;
diff --git a/src/test/isolation/expected/vacuum-concurrent-drop.out b/src/test/isolation/expected/vacuum-concurrent-drop.out
new file mode 100644
index 0000000..72d80a1
--- /dev/null
+++ b/src/test/isolation/expected/vacuum-concurrent-drop.out
@@ -0,0 +1,76 @@
+Parsed test spec with 2 sessions
+
+starting permutation: lock vac_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_specified: VACUUM test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping vacuum of "test2" --- relation no longer exists
+step vac_specified: <... completed>
+
+starting permutation: lock vac_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_all: VACUUM; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step vac_all: <... completed>
+
+starting permutation: lock analyze_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step analyze_specified: ANALYZE test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping analyze of "test2" --- relation no longer exists
+step analyze_specified: <... completed>
+
+starting permutation: lock analyze_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step analyze_all: ANALYZE; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step analyze_all: <... completed>
+
+starting permutation: lock vac_analyze_specified drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_analyze_specified: VACUUM ANALYZE test1, test2; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+WARNING:  skipping vacuum of "test2" --- relation no longer exists
+step vac_analyze_specified: <... completed>
+
+starting permutation: lock vac_analyze_all drop_and_commit
+step lock: 
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+
+step vac_analyze_all: VACUUM ANALYZE; <waiting ...>
+step drop_and_commit: 
+	DROP TABLE test2;
+	COMMIT;
+
+step vac_analyze_all: <... completed>
diff --git a/src/test/isolation/isolation_schedule b/src/test/isolation/isolation_schedule
index 32c965b..e41b916 100644
--- a/src/test/isolation/isolation_schedule
+++ b/src/test/isolation/isolation_schedule
@@ -62,3 +62,4 @@ test: sequence-ddl
 test: async-notify
 test: vacuum-reltuples
 test: timeouts
+test: vacuum-concurrent-drop
diff --git a/src/test/isolation/specs/vacuum-concurrent-drop.spec b/src/test/isolation/specs/vacuum-concurrent-drop.spec
new file mode 100644
index 0000000..31fc161
--- /dev/null
+++ b/src/test/isolation/specs/vacuum-concurrent-drop.spec
@@ -0,0 +1,45 @@
+# Test for log messages emitted by VACUUM and ANALYZE when a specified
+# relation is concurrently dropped.
+#
+# This also verifies that log messages are not emitted for concurrently
+# dropped relations that were not specified in the VACUUM or ANALYZE
+# command.
+
+setup
+{
+	CREATE TABLE test1 (a INT);
+	CREATE TABLE test2 (a INT);
+}
+
+teardown
+{
+	DROP TABLE IF EXISTS test1;
+	DROP TABLE IF EXISTS test2;
+}
+
+session "s1"
+step "lock"
+{
+	BEGIN;
+	LOCK test1 IN SHARE MODE;
+}
+step "drop_and_commit"
+{
+	DROP TABLE test2;
+	COMMIT;
+}
+
+session "s2"
+step "vac_specified"		{ VACUUM test1, test2; }
+step "vac_all"			{ VACUUM; }
+step "analyze_specified"	{ ANALYZE test1, test2; }
+step "analyze_all"		{ ANALYZE; }
+step "vac_analyze_specified"	{ VACUUM ANALYZE test1, test2; }
+step "vac_analyze_all"		{ VACUUM ANALYZE; }
+
+permutation "lock" "vac_specified" "drop_and_commit"
+permutation "lock" "vac_all" "drop_and_commit"
+permutation "lock" "analyze_specified" "drop_and_commit"
+permutation "lock" "analyze_all" "drop_and_commit"
+permutation "lock" "vac_analyze_specified" "drop_and_commit"
+permutation "lock" "vac_analyze_all" "drop_and_commit"
#15Robert Haas
robertmhaas@gmail.com
In reply to: Bossart, Nathan (#14)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

#16Bossart, Nathan
bossartn@amazon.com
In reply to: Robert Haas (#15)
Re: [HACKERS] Additional logging for VACUUM and ANALYZE

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

Committed.

Thanks!

Nathan