Hello,
I am not sure whether this should be considered a bug report or a feature
request, but I would like to report a logging behavior in auto_explain that
caused a production incident on our side.
We are using auto_explain to investigate slow queries in production, with
auto_explain.log_parameter_max_length configured in order to avoid logging very
large bind parameter values.
However, we noticed that when auto_explain.log_verbose = on,
auto_explain.log_parameter_max_length correctly limits values printed in the
Query Parameters section, but it does not limit large values printed in the
verbose plan itself, especially in Output: fields.
In our case, an application updated a large PDF stored as a bytea value. The
parameter was correctly truncated in Query Parameters, but the same large value
was printed again in the verbose plan Output: field. This generated a massive
amount of logs and filled the log filesystem, which caused a production outage.
We are sharing this because the behavior was not obvious to us from the
parameter name, and we thought it could also surprise other users who rely on
auto_explain.log_parameter_max_length as a safeguard against large logged
values.
Here is a minimal reproducer:
LOAD 'auto_explain';
SET auto_explain.log_min_duration = 0;
SET auto_explain.log_analyze = on;
SET auto_explain.log_buffers = on;
SET auto_explain.log_timing = on;
SET auto_explain.log_verbose = on;
SET auto_explain.log_parameter_max_length = 1024;
DROP TABLE IF EXISTS test_pj;
CREATE TEMP TABLE test_pj (
id bigint,
contenu bytea
);
INSERT INTO test_pj VALUES (1234567, NULL);
PREPARE upd_pj(bytea, bigint) AS
UPDATE test_pj
SET contenu = $1
WHERE id = $2;
EXECUTE upd_pj(
decode(repeat('25504446', 1024 * 256), 'hex'),
1234567
);
The Query Parameters line is correctly truncated:
Query Parameters: $1 = '\x25504446...', $2 = '1234567'
However, the verbose plan can still print a very large bytea value in the
Output: field:
Output: '\x25504446...'
This can cause massive log growth when applications update or insert large
bytea values, even though auto_explain.log_parameter_max_length is configured.
The current workaround is to disable verbose logging: auto_explain.log_verbose
= off but this also removes useful verbose plan details.
Would it make sense to add a separate setting to limit large values printed in
verbose plan fields, for example:
auto_explain.log_verbose_max_length = 1024
or:
auto_explain.log_expression_max_length = 1024
The goal would be to keep verbose plan details available while avoiding massive
log entries caused by large constants or bytea values printed in Output:.
Another possible improvement could be to mention this behavior in the
auto_explain.log_parameter_max_length documentation, so users are aware that it
only applies to Query Parameters and not to values printed by verbose plan
output.
Thanks,
Yanis
