Date: Wed, 15 May 2024 08:04:48 +0000
From: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: Log details for stats dropped more than once
Message-ID: <ZkRsoOMrSrNI945i@ip-10-97-1-34.eu-west-3.compute.internal>
References: <ZkM30paAD8Cr/Bix@ip-10-97-1-34.eu-west-3.compute.internal>
 <ZkRMcfaEesMz5MSr@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="/8qMM0nayze5naH5"
Content-Disposition: inline
In-Reply-To: <ZkRMcfaEesMz5MSr@paquier.xyz>
Archived-At: 
 <https://www.postgresql.org/message-id/ZkRsoOMrSrNI945i%40ip-10-97-1-34.eu-west-3.compute.internal>
Precedence: bulk


--/8qMM0nayze5naH5
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Hi,

On Wed, May 15, 2024 at 02:47:29PM +0900, Michael Paquier wrote:
> On Tue, May 14, 2024 at 10:07:14AM +0000, Bertrand Drouvot wrote:
> > While resuming the work on refilenode stats (mentioned in [1] but did not share
> > the patch yet), I realized that my current POC patch is buggy enough to produce
> > things like:
> > 
> > 024-05-14 09:51:14.783 UTC [1788714] FATAL:  can only drop stats once
> > 
> > While the CONTEXT provides the list of dropped stats:
> > 
> > 2024-05-14 09:51:14.783 UTC [1788714] CONTEXT:  WAL redo at 0/D75F478 for Transaction/ABORT: 2024-05-14 09:51:14.782223+00; dropped stats: 2/16384/27512/0 2/16384/27515/0 2/16384/27516/0
> 
> Can refcount be useful to know in this errcontext?

Thanks for looking at it!

Do you mean as part of the added errdetail_internal()? If so, yeah I think it's
a good idea (done that way in v2 attached).

> > Attached a tiny patch to report the stat that generates the error. The patch uses
> > errdetail_internal() as the extra details don't seem to be useful to average
> > users.
> 
> I think that's fine.  Overall that looks like useful information for
> debugging, so no objections from here.

Thanks! BTW, I just realized that adding more details for this error has already
been mentioned in [1] (and Andres did propose a slightly different version).

[1]: https://www.postgresql.org/message-id/20240505160915.6boysum4f34siqct%40awork3.anarazel.de

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

--/8qMM0nayze5naH5
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v2-0001-Log-details-for-stats-dropped-more-than-once.patch"

From 0866e8252f2038f3fdbd9cfabb214461689210df Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Date: Tue, 14 May 2024 09:10:50 +0000
Subject: [PATCH v2] Log details for stats dropped more than once

Adding errdetail_internal() in pgstat_drop_entry_internal() to display the
PgStat_HashKey and the entry's refcount when the "can only drop stats once"
error is reported.
---
 src/backend/utils/activity/pgstat_shmem.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)
 100.0% src/backend/utils/activity/

diff --git a/src/backend/utils/activity/pgstat_shmem.c b/src/backend/utils/activity/pgstat_shmem.c
index 91591da395..0595c08d6e 100644
--- a/src/backend/utils/activity/pgstat_shmem.c
+++ b/src/backend/utils/activity/pgstat_shmem.c
@@ -785,7 +785,12 @@ pgstat_drop_entry_internal(PgStatShared_HashEntry *shent,
 	 * backends to release their references.
 	 */
 	if (shent->dropped)
-		elog(ERROR, "can only drop stats once");
+		ereport(ERROR,
+				errmsg("can only drop stats once"),
+				errdetail_internal("Stats kind=%s dboid=%u objoid=%u refcount=%u.",
+								   pgstat_get_kind_info(shent->key.kind)->name,
+								   shent->key.dboid, shent->key.objoid,
+								   pg_atomic_read_u32(&shent->refcount)));
 	shent->dropped = true;
 
 	/* release refcount marking entry as not dropped */
-- 
2.34.1


--/8qMM0nayze5naH5--