Logging query parmeters in auto_explain

Dagfinn Ilmari Mannsåker <ilmari@ilmari.org> writes:

Hi hackers,

Inspired by a question on IRC, I noticed that while the core statement
logging system gained the option to log statement parameters in PG 13,
auto_explain was left out.

Here's a patch that adds a corresponding
auto_explain.log_parameter_max_length config setting, which controls the
"Query Parameters" node in the logged plan. Just like in core, the
default is -1, which logs the parameters in full, and 0 disables
parameter logging, while any other value truncates each parameter to
that many bytes.

I've added added it to the upcoming commitfest:

https://commitfest.postgresql.org/38/3660/

- ilmari

On Tue, May 31, 2022 at 09:33:20PM +0100, Dagfinn Ilmari Mannsåker wrote:

Here's a patch that adds a corresponding
auto_explain.log_parameter_max_length config setting, which controls the
"Query Parameters" node in the logged plan. Just like in core, the
default is -1, which logs the parameters in full, and 0 disables
parameter logging, while any other value truncates each parameter to
that many bytes.

With a behavior similar to the in-core log_parameter_max_length, this
looks rather sane to me. This is consistent with the assumptions of
errdetail_params().

+$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = -1");
Nit.  You don't need this change in the TAP test, as this is the
default value to log everything.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:

On Tue, May 31, 2022 at 09:33:20PM +0100, Dagfinn Ilmari Mannsåker wrote:

Here's a patch that adds a corresponding
auto_explain.log_parameter_max_length config setting, which controls the
"Query Parameters" node in the logged plan. Just like in core, the
default is -1, which logs the parameters in full, and 0 disables
parameter logging, while any other value truncates each parameter to
that many bytes.

With a behavior similar to the in-core log_parameter_max_length, this
looks rather sane to me. This is consistent with the assumptions of
errdetail_params().

That was the intention, yes.

+$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = -1");
Nit. You don't need this change in the TAP test, as this is the
default value to log everything.

Point, fixed in the attached v2. I've also added a test that truncation
and disabling works.

- ilmari

On Tue, Jun 07, 2022 at 12:18:52PM +0100, Dagfinn Ilmari Mannsåker wrote:

Point, fixed in the attached v2. I've also added a test that truncation
and disabling works.

The tests are structured so as all the queries are run first, then the
full set of logs is slurped and scanned. With things like tests for
truncation, it becomes easier to have a given test overlap with
another one in terms of pattern matching, so we could silently lose
coverage. Wouldn't it be better to reorganize things so we save the
current size of the log file (as of -s $node->logfile), run one query,
and then slurp the log file based on the position saved previously?
The GUC updates had better be localized in each sub-section of the
tests, as well.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:

On Tue, Jun 07, 2022 at 12:18:52PM +0100, Dagfinn Ilmari Mannsåker wrote:

Point, fixed in the attached v2. I've also added a test that truncation
and disabling works.

The tests are structured so as all the queries are run first, then the
full set of logs is slurped and scanned. With things like tests for
truncation, it becomes easier to have a given test overlap with
another one in terms of pattern matching, so we could silently lose
coverage. Wouldn't it be better to reorganize things so we save the
current size of the log file (as of -s $node->logfile), run one query,
and then slurp the log file based on the position saved previously?
The GUC updates had better be localized in each sub-section of the
tests, as well.

Done (and more tests added), v3 attached.

- ilmari

On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:

Done (and more tests added), v3 attached.

One thing I am wondering is if we'd better mention errdetail_params()
at the top of the initial check done in ExplainQueryParameters().
That's a minor issue, though.

+sub query_log
+{
Perhaps a short description at the top of this routine to explain it
is worth it? The test still does a set of like() and unlike() after
running each query when the parameter updates are done. One thing I
would have played with is to group the set of logs expected or not
expected as parameters of the centralized routine, but that would
reduce the customization of the test names, so at the end the approach
you have taken for query_log() looks good to me.

+$node->stop('fast');
There is no need for that. The END block of Cluster.pm does that
already.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:

On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:

Done (and more tests added), v3 attached.

One thing I am wondering is if we'd better mention errdetail_params()
at the top of the initial check done in ExplainQueryParameters().
That's a minor issue, though.

+sub query_log
+{
Perhaps a short description at the top of this routine to explain it
is worth it?

Done. I also moved the function to the bottom of the file, to avoid
distracting from the actual test queries.

The test still does a set of like() and unlike() after running each
query when the parameter updates are done. One thing I would have
played with is to group the set of logs expected or not expected as
parameters of the centralized routine, but that would reduce the
customization of the test names, so at the end the approach you have
taken for query_log() looks good to me.

I did consider passing the tests as a data structure to the function,
but that would amount to specifying exactly the same things but as a
data structure, and then calling the appropriate function by reference,
which just makes things more cluttered.

If we were using TAP subtests, it might make a sense to have the
function run each set of related tests in a subtest, rather than having
multiple subtest calls at the top level, but we don't, so it doesn't.

+$node->stop('fast');
There is no need for that. The END block of Cluster.pm does that
already.

Ah, I was not aware of that. The call was there in the original version,
so I had just left it in. Removed.

v4 patch attached.

- ilmari

Dagfinn Ilmari Mannsåker <ilmari@ilmari.org> writes:

Michael Paquier <michael@paquier.xyz> writes:

On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:

Done (and more tests added), v3 attached.

One thing I am wondering is if we'd better mention errdetail_params()
at the top of the initial check done in ExplainQueryParameters().
That's a minor issue, though.

+sub query_log
+{
Perhaps a short description at the top of this routine to explain it
is worth it?

Done. I also moved the function to the bottom of the file, to avoid
distracting from the actual test queries.

I forgot to mention, I also changed the order of the query and
parameters, so that they can more naturally be left out when no changes
are needed.

- ilmari

On Mon, Jun 27, 2022 at 12:27:57PM +0100, Dagfinn Ilmari Mannsåker wrote:

I forgot to mention, I also changed the order of the query and
parameters, so that they can more naturally be left out when no changes
are needed.

I can see that, and I have added $node as an extra parameter of the
routine. After putting my hands on that, it also felt a bit unnatural
to do the refactoring of the tests and the addition of the new GUC in
the same patch, so I have split things as the attached. The amount of
coverage is still the same but it makes the integration of the feature
easier to follow.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:

On Mon, Jun 27, 2022 at 12:27:57PM +0100, Dagfinn Ilmari Mannsåker wrote:

I forgot to mention, I also changed the order of the query and
parameters, so that they can more naturally be left out when no changes
are needed.

I can see that, and I have added $node as an extra parameter of the
routine. After putting my hands on that, it also felt a bit unnatural
to do the refactoring of the tests and the addition of the new GUC in
the same patch, so I have split things as the attached. The amount of
coverage is still the same but it makes the integration of the feature
easier to follow.

That makes sense, but I still think the query_log() function definition
should go at the end (after done_testing()), so the machinery doesn't
distract from what's actually being tested.

Also, the second paragraph of the second commit message now belongs in
the first commit (without the word "Also").

Thanks,
ilmari

On Tue, Jun 28, 2022 at 10:12:18AM +0100, Dagfinn Ilmari Mannsåker wrote:

That makes sense, but I still think the query_log() function definition
should go at the end (after done_testing()), so the machinery doesn't
distract from what's actually being tested.

The majority of TAP scripts have their subroutines at the beginning of
the script, and there are few having that at the end. I won't fight
you on that, but the former is more consistent.

Also, the second paragraph of the second commit message now belongs in
the first commit (without the word "Also").

Yep, will fix. I usually rewrite commit messages before merging them.
--
Michael

On Wed, Jun 29, 2022 at 09:17:49AM +0900, Michael Paquier wrote:

The majority of TAP scripts have their subroutines at the beginning of
the script, and there are few having that at the end. I won't fight
you on that, but the former is more consistent.

I have kept things as I originally intended, and applied 0001 for the
refactoring pieces.
--
Michael

On Fri, Jul 01, 2022 at 09:58:52AM +0900, Michael Paquier wrote:

I have kept things as I originally intended, and applied 0001 for the
refactoring pieces.

And done as well with 0002. So we are good for this thread.
--
Michael

On Wed, 6 Jul 2022, at 02:02, Michael Paquier wrote:

On Fri, Jul 01, 2022 at 09:58:52AM +0900, Michael Paquier wrote:

I have kept things as I originally intended, and applied 0001 for the
refactoring pieces.

And done as well with 0002. So we are good for this thread.

Thanks!

- ilmari