Обсуждение: auto_explain logs ERROR: 08P01 for every query using bind variable
To whom it may concern,
For performance and security, most of our queries use bind variables. We also implemented auto_explain for tracking down un-optimized queries. Our database supports a large application. During the work-hours, there are 30,000+ queries executed every hour. PostgreSQL logs rotates every hour and each log contains 30,000+ error message like below.
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR: ERROR: 08P01: bind message supplies 0 parameters, but prepared statement "..." requires 1
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION: exec_bind_message, postgres.c:1601
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT: EXPLAIN select ...,...,..,... from ... where ....=$1
These error messages are really overwhelming to us and they are not useful at all. In our opinion, these error messages should not be logged.
Best Regards,
Ted Liu
On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:
To whom it may concern,For performance and security, most of our queries use bind variables. We also implemented auto_explain for tracking down un-optimized queries. Our database supports a large application. During the work-hours, there are 30,000+ queries executed every hour. PostgreSQL logs rotates every hour and each log contains 30,000+ error message like below.2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR: ERROR: 08P01: bind message supplies 0 parameters, but prepared statement "..." requires 12020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION: exec_bind_message, postgres.c:16012020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT: EXPLAIN select ...,...,..,... from ... where ....=$1These error messages are really overwhelming to us and they are not useful at all. In our opinion, these error messages should not be logged.
I agree they shouldn't be logged. And I don't get such messages when using auto_explain with something like `pgbench -M prepared`.
What version are you using? What settings are you using for auto_explain? What is your client language/driver? Maybe the client is doing something weird like sending duplicate binds?
Cheers,
Jeff
Hi Jeff,
Thank you for looking into this issue.
Our Postgres version is 11.5. The auto_explain settings are
name | setting
------------------------------------+---------
auto_explain.log_analyze | off
auto_explain.log_buffers | off
auto_explain.log_format | text
auto_explain.log_min_duration | 190000
auto_explain.log_nested_statements | off
auto_explain.log_timing | on
auto_explain.log_triggers | off
auto_explain.log_verbose | off
auto_explain.sample_rate | 1
(9 rows)
Thanks,
Ted
On Friday, January 31, 2020, 9:52:51 AM EST, Jeff Janes <jeff.janes@gmail.com> wrote:
On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:
To whom it may concern,For performance and security, most of our queries use bind variables. We also implemented auto_explain for tracking down un-optimized queries. Our database supports a large application. During the work-hours, there are 30,000+ queries executed every hour. PostgreSQL logs rotates every hour and each log contains 30,000+ error message like below.2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR: ERROR: 08P01: bind message supplies 0 parameters, but prepared statement "..." requires 12020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION: exec_bind_message, postgres.c:16012020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT: EXPLAIN select ...,...,..,... from ... where ....=$1These error messages are really overwhelming to us and they are not useful at all. In our opinion, these error messages should not be logged.
I agree they shouldn't be logged. And I don't get such messages when using auto_explain with something like `pgbench -M prepared`.
What version are you using? What settings are you using for auto_explain? What is your client language/driver? Maybe the client is doing something weird like sending duplicate binds?
Cheers,
Jeff
Jeff Janes <jeff.janes@gmail.com> writes:
> On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:
>> For performance and security, most of our queries use bind variables. We
>> also implemented auto_explain for tracking down un-optimized queries. Our
>> database supports a large application. During the work-hours, there are
>> 30,000+ queries executed every hour. PostgreSQL logs rotates every hour and
>> each log contains 30,000+ error message like below.
>>
>> 2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR:
>> ERROR: 08P01: bind message supplies 0 parameters, but prepared statement
>> "..." requires 1
>> 2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION:
>> exec_bind_message, postgres.c:1601
>> 2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT:
>> EXPLAIN select ...,...,..,... from ... where ....=$1
> I agree they shouldn't be logged. And I don't get such messages when using
> auto_explain with something like `pgbench -M prepared`.
Surely these are reporting a genuine client-side logic error. You
need to fix your application, not complain about the fact that we're
reporting that it's broken. (Note that auto_explain does NOT issue
"EXPLAIN" commands; it works at a lower level than that. These
EXPLAIN commands are coming from a client application.)
If you really don't care to get log messages about incorrect queries,
you could always set log_min_messages higher than ERROR ...
regards, tom lane