pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedLog details for stats dropped more than once
4+ messages / 2 participants
[nested] [flat]
Commits from this thread:
2024-06-07 d92573adcb 83f415e2d9 2de059de2c Add more debugging information when dropping twice pgstats entry
* Log details for stats dropped more than once
@ 2024-05-14 10:07 Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 05:47 ` Re: Log details for stats dropped more than once Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 4+ messages in thread
From: Bertrand Drouvot @ 2024-05-14 10:07 UTC (permalink / raw)
To: pgsql-hackers@lists.postgresql.org
Hi hackers,
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
It's not clear which one generates the error (don't pay attention to the actual
values, the issue comes from the new refilenode stats that I removed from the
output).
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.
[1]: https://www.postgresql.org/message-id/ZbIdgTjR2QcFJ2mE%40ip-10-97-1-34.eu-west-3.compute.internal
Looking forward to your feedback,
Regards
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
Attachments:
v1-0001-Log-details-for-stats-dropped-more-than-once.patch (text/x-diff, 1.2K) download
From f296d4092f5e87ed63a323db3f1bc9cfa807e2e8 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 v1] Log details for stats dropped more than once
Adding errdetail_internal() in pgstat_drop_entry_internal() to display the
PgStat_HashKey when the "can only drop stats once" error is reported.
---
src/backend/utils/activity/pgstat_shmem.c | 6 +++++-
1 file changed, 5 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..1308c4439a 100644
--- a/src/backend/utils/activity/pgstat_shmem.c
+++ b/src/backend/utils/activity/pgstat_shmem.c
@@ -785,7 +785,11 @@ 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.",
+ pgstat_get_kind_info(shent->key.kind)->name,
+ shent->key.dboid, shent->key.objoid));
shent->dropped = true;
/* release refcount marking entry as not dropped */
--
2.34.1
* Re: Log details for stats dropped more than once
2024-05-14 10:07 Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
@ 2024-05-15 05:47 ` Michael Paquier <michael@paquier.xyz>
2024-05-15 08:04 ` Re: Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
0 siblings, 1 reply; 4+ messages in thread
From: Michael Paquier @ 2024-05-15 05:47 UTC (permalink / raw)
To: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>; +Cc: pgsql-hackers@lists.postgresql.org
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?
> 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.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Log details for stats dropped more than once
2024-05-14 10:07 Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 05:47 ` Re: Log details for stats dropped more than once Michael Paquier <michael@paquier.xyz>
@ 2024-05-15 08:04 ` Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 23:17 ` Re: Log details for stats dropped more than once Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 4+ messages in thread
From: Bertrand Drouvot @ 2024-05-15 08:04 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
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
Attachments:
v2-0001-Log-details-for-stats-dropped-more-than-once.patch (text/x-diff, 1.3K) download
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
* Re: Log details for stats dropped more than once
2024-05-14 10:07 Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 05:47 ` Re: Log details for stats dropped more than once Michael Paquier <michael@paquier.xyz>
2024-05-15 08:04 ` Re: Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
@ 2024-05-15 23:17 ` Michael Paquier <michael@paquier.xyz>
0 siblings, 0 replies; 4+ messages in thread
From: Michael Paquier @ 2024-05-15 23:17 UTC (permalink / raw)
To: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>; +Cc: pgsql-hackers@lists.postgresql.org
On Wed, May 15, 2024 at 08:04:48AM +0000, Bertrand Drouvot wrote:
> 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
Ah, it is not surprising. I'd agree with doing what is posted there
for simplicity's sake. Rather than putting that in a errdetail, let's
keep all the information in an errmsg() as that makes deparsing
easier, and let's keep the elog().
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 4+ messages in thread
end of thread, other threads:[~2024-05-15 23:17 UTC | newest]
Thread overview: 4+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2024-05-14 10:07 Log details for stats dropped more than once Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 05:47 ` Michael Paquier <michael@paquier.xyz>
2024-05-15 08:04 ` Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
2024-05-15 23:17 ` Michael Paquier <michael@paquier.xyz>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox