Problems around compute_query_id
Hi all,
Starting a new thread as the one that has introduced compute_query_id
is already long enough.
Fujii-san has reported on Twitter that enabling the computation of
query IDs does not work properly with log_statement as the query ID is
calculated at parse analyze time and the query is logged before that.
As far as I can see, that's really a problem as any queries logged are
combined with a query ID of 0, and log parsers would not really be
able to use that, even if the information provided by for example
log_duration gives the computed query ID prevent in pg_stat_activity.
While making the feature run on some test server, I have noticed that
%Q would log some garbage query ID for autovacuum workers that's kept
around. That looks wrong.
Thoughts?
--
Michael
On Mon, Apr 12, 2021 at 03:12:40PM +0900, Michael Paquier wrote:
Hi all,
Starting a new thread as the one that has introduced compute_query_id
is already long enough.Fujii-san has reported on Twitter that enabling the computation of
query IDs does not work properly with log_statement as the query ID is
calculated at parse analyze time and the query is logged before that.
As far as I can see, that's really a problem as any queries logged are
combined with a query ID of 0, and log parsers would not really be
able to use that, even if the information provided by for example
log_duration gives the computed query ID prevent in pg_stat_activity.
I don't see any way around that. The goal of log_statements is to log all
syntactically valid queries, including otherwise invalid queries. For
instance, it would log
SELECT notacolumn;
and there's no way to compute a queryid in that case. I think that
log_statements already causes some issues with log parsers. At least pgbadger
recommends to avoid using that:
"Do not enable log_statement as its log format will not be parsed by pgBadger."
I think we should simply document that %Q is not compatible with
log_statements.
While making the feature run on some test server, I have noticed that
%Q would log some garbage query ID for autovacuum workers that's kept
around. That looks wrong.
I've not been able to reproduce it, do you have some hint on how to do it?
Maybe setting a zero queryid at the beginning of AutoVacWorkerMain() could fix
the problem?
Hi,
On Mon, Apr 12, 2021 at 02:56:59PM +0800, Julien Rouhaud wrote:
On Mon, Apr 12, 2021 at 03:12:40PM +0900, Michael Paquier wrote:
Fujii-san has reported on Twitter that enabling the computation of
query IDs does not work properly with log_statement as the query ID is
calculated at parse analyze time and the query is logged before that.
As far as I can see, that's really a problem as any queries logged are
combined with a query ID of 0, and log parsers would not really be
able to use that, even if the information provided by for example
log_duration gives the computed query ID prevent in pg_stat_activity.I don't see any way around that. The goal of log_statements is to log all
syntactically valid queries, including otherwise invalid queries. For
instance, it would logSELECT notacolumn;
and there's no way to compute a queryid in that case. I think that
log_statements already causes some issues with log parsers. At least pgbadger
recommends to avoid using that:"Do not enable log_statement as its log format will not be parsed by pgBadger."
I think we should simply document that %Q is not compatible with
log_statements.
What about log_statement_sample_rate ? Does compute_query_id have the
same problem with that?
Michael
--
Michael Banck
Projektleiter / Senior Berater
Tel.: +49 2166 9901-171
Fax: +49 2166 9901-100
Email: michael.banck@credativ.de
credativ GmbH, HRB M�nchengladbach 12080
USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 M�nchengladbach
Gesch�ftsf�hrung: Dr. Michael Meskes, Sascha Heuer
Unser Umgang mit personenbezogenen Daten unterliegt
folgenden Bestimmungen: https://www.credativ.de/datenschutz
On Mon, Apr 12, 2021 at 09:20:07AM +0200, Michael Banck wrote:
What about log_statement_sample_rate ? Does compute_query_id have the
same problem with that?
No, log_statement_sample_rate samples log_min_duration_statements, not
log_statements so it works as expected.
On Mon, Apr 12, 2021 at 03:26:33PM +0800, Julien Rouhaud wrote:
On Mon, Apr 12, 2021 at 09:20:07AM +0200, Michael Banck wrote:
What about log_statement_sample_rate ? Does compute_query_id have the
same problem with that?No, log_statement_sample_rate samples log_min_duration_statements, not
log_statements so it works as expected.
While on that topic, it's probably worth mentioning that log_duration is now
way more useful if you have the queryid in you log_line_prefix. It avoids to
log the full query text while still being able to know what was the underlying
normalized query by dumping the content of pg_stat_statements.
On Mon, Apr 12, 2021 at 02:56:59PM +0800, Julien Rouhaud wrote:
I think we should simply document that %Q is not compatible with
log_statements.
Hearing no objection I documented that limitation.
While making the feature run on some test server, I have noticed that
%Q would log some garbage query ID for autovacuum workers that's kept
around. That looks wrong.I've not been able to reproduce it, do you have some hint on how to do it?
Maybe setting a zero queryid at the beginning of AutoVacWorkerMain() could fix
the problem?
It turns out that the problem was simply that some process can inherit a
PgBackendStatus for which a previous backend reported a queryid. For processes
like autovacuum process, they will never report a new identifier so they
reported the previous one. Resetting the field like the other ones in
pgstat_bestart() fixes the problem for autovacuum and any similar process.
Attachments:
v1-0001-Additional-fixes-for-compute_query_id.patchtext/x-diff; charset=us-asciiDownload
From eb8a90b88d8572b110535c6350830cf58632fecd Mon Sep 17 00:00:00 2001
From: Julien Rouhaud <julien.rouhaud@free.fr>
Date: Thu, 15 Apr 2021 15:28:03 +0800
Subject: [PATCH v1] Additional fixes for compute_query_id.
Statements logged by log_statement parameter always get a zero queryid. This
is a limitation due to how log_statement is implemented, as it logs all wanted
synctatically valid statements before an indentifier can be calculated,
including invalid statements such as
SELECT not_a_column;
for which an identifier can't be calculated, so document that limitation.
It was also possible that a new process ends up emitting logs with an incorrect
query identifier if the previous PgBackendStatus user reported an identifier as
the pgstat field wasn't correctly reset.
Author: Julien Rouhaud
Reported-by: Fuji Masao
Reported-by: Michael Paquier
Discussion: https://postgr.es/m/YHPkU8hFi4no4NSw@paquier.xyz
---
doc/src/sgml/config.sgml | 10 ++++++++++
src/backend/utils/activity/backend_status.c | 1 +
2 files changed, 11 insertions(+)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 776ab1a8c8..d5735b72c8 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7139,6 +7139,16 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</programlisting>
</para>
</tip>
+
+ <note>
+ <para>
+ The <literal>%Q</literal> escape will always report a zero identifier
+ when used together with <xref linkend="guc-log-statement"/> as this
+ parameter logs statements before an identifier can be calculated,
+ including invalid statements for which an identifier cannot be
+ calculated.
+ </para>
+ </note>
</listitem>
</varlistentry>
diff --git a/src/backend/utils/activity/backend_status.c b/src/backend/utils/activity/backend_status.c
index 6110113e56..80ffcdf6de 100644
--- a/src/backend/utils/activity/backend_status.c
+++ b/src/backend/utils/activity/backend_status.c
@@ -398,6 +398,7 @@ pgstat_bestart(void)
lbeentry.st_state = STATE_UNDEFINED;
lbeentry.st_progress_command = PROGRESS_COMMAND_INVALID;
lbeentry.st_progress_command_target = InvalidOid;
+ lbeentry.st_queryid = UINT64CONST(0);
/*
* we don't zero st_progress_param here to save cycles; nobody should
--
2.30.1
On Thu, Apr 15, 2021 at 03:43:59PM +0800, Julien Rouhaud wrote:
On Mon, Apr 12, 2021 at 02:56:59PM +0800, Julien Rouhaud wrote:
I think we should simply document that %Q is not compatible with
log_statements.Hearing no objection I documented that limitation.
While making the feature run on some test server, I have noticed that
%Q would log some garbage query ID for autovacuum workers that's kept
around. That looks wrong.I've not been able to reproduce it, do you have some hint on how to do it?
Maybe setting a zero queryid at the beginning of AutoVacWorkerMain() could fix
the problem?It turns out that the problem was simply that some process can inherit a
PgBackendStatus for which a previous backend reported a queryid. For processes
like autovacuum process, they will never report a new identifier so they
reported the previous one. Resetting the field like the other ones in
pgstat_bestart() fixes the problem for autovacuum and any similar process.
I slightly adjusted the patch and applied it. Thanks. I think this
closes all the open issues around query_id. :-)
--
Bruce Momjian <bruce@momjian.us> https://momjian.us
EDB https://enterprisedb.com
If only the physical world exists, free will is an illusion.
Attachments:
master.difftext/x-diff; charset=us-asciiDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 776ab1a8c8..dd7ebe7a9d 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7139,6 +7139,16 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</programlisting>
</para>
</tip>
+
+ <note>
+ <para>
+ The <literal>%Q</literal> escape always reports a zero identifier
+ for lines output by <xref linkend="guc-log-statement"/> because
+ <varname>log_statement</varname> generates output before an
+ identifier can be calculated, including invalid statements for
+ which an identifier cannot be calculated.
+ </para>
+ </note>
</listitem>
</varlistentry>
diff --git a/src/backend/utils/activity/backend_status.c b/src/backend/utils/activity/backend_status.c
index 787f062f9c..a368101103 100644
--- a/src/backend/utils/activity/backend_status.c
+++ b/src/backend/utils/activity/backend_status.c
@@ -398,6 +398,7 @@ pgstat_bestart(void)
lbeentry.st_state = STATE_UNDEFINED;
lbeentry.st_progress_command = PROGRESS_COMMAND_INVALID;
lbeentry.st_progress_command_target = InvalidOid;
+ lbeentry.st_query_id = UINT64CONST(0);
/*
* we don't zero st_progress_param here to save cycles; nobody should
On Tue, Apr 20, 2021 at 12:59:10PM -0400, Bruce Momjian wrote:
On Thu, Apr 15, 2021 at 03:43:59PM +0800, Julien Rouhaud wrote:
On Mon, Apr 12, 2021 at 02:56:59PM +0800, Julien Rouhaud wrote:
I think we should simply document that %Q is not compatible with
log_statements.Hearing no objection I documented that limitation.
While making the feature run on some test server, I have noticed that
%Q would log some garbage query ID for autovacuum workers that's kept
around. That looks wrong.I've not been able to reproduce it, do you have some hint on how to do it?
Maybe setting a zero queryid at the beginning of AutoVacWorkerMain() could fix
the problem?It turns out that the problem was simply that some process can inherit a
PgBackendStatus for which a previous backend reported a queryid. For processes
like autovacuum process, they will never report a new identifier so they
reported the previous one. Resetting the field like the other ones in
pgstat_bestart() fixes the problem for autovacuum and any similar process.I slightly adjusted the patch and applied it. Thanks. I think this
closes all the open issues around query_id. :-)
Thanks a lot Bruce! There was also [1]/messages/by-id/CAJcOf-fXyb2QiDbwftD813UF70w-+BsK-03bFp1GrijXU9GQYQ@mail.gmail.com, but Michael already committed the
proposed fix, so I also think that all open issues for query_id are not taken
care of!
[1]: /messages/by-id/CAJcOf-fXyb2QiDbwftD813UF70w-+BsK-03bFp1GrijXU9GQYQ@mail.gmail.com