log bind parameter values on error

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

log bind parameter values on error

bashtanov
Hello,

I'd like to propose a patch to log bind parameter values not only when
logging duration,
but also on error (timeout in particular) or in whatever situation the
statement normally gets logged.
This mostly could be useful when the request originator doesn't log them
either, so it's hard
to reproduce the problem.

Unfortunately, when enabled, the feature comes with some memory and CPU
overhead,
as we cannot convert certain values to text when in aborted transaction.

We potentially could do the trick with built-in types, but it would need
cautious work with composite types,
and also require more computation on the logging stage, which is a risk
of cascading errors.
Custom types still wouldn't be loggable, even as passed by client, which
would be not great.

So I decided to cache textual representations on bind stage,
which is especially easy if the client uses text protocol.

Best,
   Alexey

log_parameters_v001.patch (23K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Peter Eisentraut-6
On 15/12/2018 00:04, Alexey Bashtanov wrote:
> I'd like to propose a patch to log bind parameter values not only when
> logging duration,
> but also on error (timeout in particular) or in whatever situation the
> statement normally gets logged.
> This mostly could be useful when the request originator doesn't log them
> either, so it's hard
> to reproduce the problem.

That's a reasonable problem to solve.

> So I decided to cache textual representations on bind stage,
> which is especially easy if the client uses text protocol.

That sounds like a plausible approach.  Have you done any performance
measurements?

In your patch, I would organize the changes to the portal API a bit
differently.  Don't change the signature of CreatePortal().  Get rid of
PortalSetCurrentTop() and PortalClearCurrentTop().  Just have a global
variable CurrentPortal and set it directly.  And then change
GetCurrentPortalBindParameters() to take a Portal as argument.  This can
all happen inside postgres.c without changing the Portal APIs.

In fact, maybe don't use the Portal structure at all and just store the
saved textualized values inside postgres.c in a static variable.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

bashtanov

> That sounds like a plausible approach.  Have you done any performance
> measurements?

No I haven't yet

> In your patch, I would organize the changes to the portal API a bit
> differently.  Don't change the signature of CreatePortal().
okay
> Get rid of PortalSetCurrentTop() and PortalClearCurrentTop().

I'll remove them from Portal API, but possibly have them in postgres.c
if you don't mind, just to avoid code duplication.
Renamed and maybe even inlined.

> Just have a global
> variable CurrentPortal and set it directly.  And then change
> GetCurrentPortalBindParameters() to take a Portal as argument.  This can
> all happen inside postgres.c without changing the Portal APIs.
Okay, will do
> In fact, maybe don't use the Portal structure at all and just store the
> saved textualized values inside postgres.c in a static variable.

Unlike SQL, parameters may spend much more memory, so I'd have them
in portal memory context to make sure the memory is released earlier
rather than later.
Tracking individual variable lifetime like we do with debug_query_string
sounds doable but a bit non-straightforward to me,
see e.g. the tricks we do with transaction commands.

Also, I'd like to avoid early forming of the error string, as we may
need to combine
them differently in future, e.g. when logging in various logging formats
or languages.
One-by-one pfree-ing doesn't look tempting either.

Do you think it would be acceptable to leave them cached in parameters
structure?

Best,
   Alex


Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Peter Eisentraut-6
On 02/01/2019 23:53, Alexey Bashtanov wrote:
>> In fact, maybe don't use the Portal structure at all and just store the
>> saved textualized values inside postgres.c in a static variable.
>
> Unlike SQL, parameters may spend much more memory, so I'd have them
> in portal memory context to make sure the memory is released earlier
> rather than later.

Having them in the portal structure is different from having it in the
portal memory context.  Although there is perhaps value in keeping them
together.

> Do you think it would be acceptable to leave them cached in parameters
> structure?

Let's see how it looks.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

bashtanov
Hello Peter,

>> Unlike SQL, parameters may spend much more memory, so I'd have them
>> in portal memory context to make sure the memory is released earlier
>> rather than later.
> Having them in the portal structure is different from having it in the
> portal memory context.  Although there is perhaps value in keeping them
> together.
yeah, to avoid pointers to deallocated areas

> Let's see how it looks.
>
please see attached

Best,
   Alex

log_parameters_v002.patch (22K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

bashtanov

> please see attached
sorry, some unintended changes sneaked in, please see the corrected patch

log_parameters_v003.patch (20K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Peter Eisentraut-6
There appears to be a problem with how this affects current logging
behavior.

I'm using

    pgbench -M extended -S -T 10 bench

to test the extended protocol.

Unpatched, with log_statement=all, you get something like

LOG:  execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
= $1;
DETAIL:  parameters: $1 = '30223'

With your patch, with log_statement=all and log_parameters=on, you get
the same, but with log_statement=all and log_parameters=off you get

LOG:  execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
= $1;
DETAIL:  parameters: $1 = UNKNOWN TYPE

We should probably keep the existing parameter logging working as before.

This also raises the question of the new parameter name.  Parameters are
already logged.  So the name should perhaps be more like
log_parameters_on_error.

Some API notes on your patch:  I think you can change
get_portal_bind_parameters() to take a ParamListInfo, since you're not
doing anything with the Portal other than grab the parameters.  And that
would allow you to keep the signature of errdetail_params() unchanged.

I did some performance tests using the commands shown above and didn't
find any problems.  Obviously the default pgbench stuff isn't very
parameter-intensive.  Do you have tests with more and larger parameter
values?

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

bashtanov
Hi Peter,

> With your patch, with log_statement=all and log_parameters=on, you get
> the same, but with log_statement=all and log_parameters=off you get
>
> LOG:  execute <unnamed>: SELECT abalance FROM pgbench_accounts WHERE aid
> = $1;
> DETAIL:  parameters: $1 = UNKNOWN TYPE
Thanks for spotting this, I've fixed it, see the new patch attached.
> This also raises the question of the new parameter name.  Parameters are
> already logged.  So the name should perhaps be more like
> log_parameters_on_error.
Done
> Some API notes on your patch:  I think you can change
> get_portal_bind_parameters() to take a ParamListInfo, since you're not
> doing anything with the Portal other than grab the parameters.  And that
> would allow you to keep the signature of errdetail_params() unchanged.
Done
> I did some performance tests using the commands shown above and didn't
> find any problems.  Obviously the default pgbench stuff isn't very
> parameter-intensive.  Do you have tests with more and larger parameter
> values?
>

I've done some tests, but they are not very reproducible:
the difference between runs is more than the difference between master
vs feature branch
and log_parameters_on_error on vs off.

I was using a small java app, it tested the speed using only a single
connection.
See its code and the results attached.

I'm sorry for the delay, feel free to move it to next commitfest if needed.

Best,
   Alex

JDBCTest.java (2K) Download Attachment
params_benchmark.txt (3K) Download Attachment
log_parameters_v005.patch (19K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Michael Paquier-2
On Mon, Jan 28, 2019 at 12:15:51AM +0000, Alexey Bashtanov wrote:
> I'm sorry for the delay, feel free to move it to next commitfest if
> needed.

Done.
--
Michael

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Peter Eisentraut-6
In reply to this post by bashtanov
This piece in your patch probably doesn't belong:

+                       elog(WARNING, "params->hasTextValues=%d,
IsAbortedTransactionBlockState()=%d",
+                                          params->hasTextValues &&
IsAbortedTransactionBlockState());

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Andres Freund
In reply to this post by bashtanov
Hi,

On 2018-12-14 23:04:26 +0000, Alexey Bashtanov wrote:
> Unfortunately, when enabled, the feature comes with some memory and CPU
> overhead,
> as we cannot convert certain values to text when in aborted transaction.

Have you analyzed how invasive it'd be to delay that till we actually
can safely start a [sub]transaction to do that logging? Probably too
expensive, but it seems like something that ought to be analyzed.

- Andres

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

Andres Freund
In reply to this post by bashtanov
Hi,

tiny scroll-through review.

On 2019-01-28 00:15:51 +0000, Alexey Bashtanov wrote:

> diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
> index b6f5822..997e6e8 100644
> --- a/doc/src/sgml/config.sgml
> +++ b/doc/src/sgml/config.sgml
> @@ -6274,6 +6274,23 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
>        </listitem>
>       </varlistentry>
>  
> +     <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
> +      <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
> +      <indexterm>
> +       <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
> +      </indexterm>
> +      </term>
> +      <listitem>
> +       <para>
> +        Controls whether the statement is logged with bind parameter values.
> +        It adds some overhead, as postgres will cache textual
> +        representations of parameter values in memory for all statements,
> +        even if they eventually do not get logged. The default is
> +        <literal>off</literal>. Only superusers can change this setting.
> +       </para>
> +      </listitem>
> +     </varlistentry>

This needs a bit of language polishing.



> @@ -31,6 +31,8 @@
>   * set of parameter values.  If dynamic parameter hooks are present, we
>   * intentionally do not copy them into the result.  Rather, we forcibly
>   * instantiate all available parameter values and copy the datum values.
> + *
> + * We don't copy textual representations here.
>   */

That probably needs to be expanded on. Including a comment about what
guarantees that there are no memory lifetime issues.


> - /* Free result of encoding conversion, if any */
> - if (pstring && pstring != pbuf.data)
> - pfree(pstring);
> + if (pstring)
> + {
> + if (need_text_values)
> + {
> + if (pstring == pbuf.data)
> + {
> + /*
> + * Copy textual representation to portal context.
> + */
> + params->params[paramno].textValue =
> + pstrdup(pstring);
> + }
> + else
> + {
> + /* Reuse the result of encoding conversion for it */
> + params->params[paramno].textValue = pstring;
> + }
> + }
> + else
> + {
> + /* Free result of encoding conversion */
> + if (pstring != pbuf.data)
> + pfree(pstring);
> + }
> + }

So the parameters we log here haven't actually gone through the output
function? Isn't that an issue? I mean that'll cause the contents to
differ from the non-error case, no? And differs from the binary protocol
case?

>   else
>   {
> + /*
> + * We do it for non-xact commands only, as an xact command
> + * 1) shouldn't have any parameters to log;
> + * 2) may have the portal dropped early.
> + */
> + Assert(current_top_portal == NULL);
> + current_top_portal = portal;
> + portalParams = NULL;
> +

"it"? ISTM the comment doesn't really stand on its own?



> +/*
> + * get_portal_bind_parameters
> + * Get the string containing parameters data, is used for logging.
> + *
> + * Can return NULL if there are no parameters in the portal
> + * or the portal is not valid, or the text representations of the parameters are
> + * not available. If returning a non-NULL value, it allocates memory
> + * for the returned string in the current context, and it's the caller's
> + * responsibility to pfree() it if needed.
> + */
> +char *
> +get_portal_bind_parameters(ParamListInfo params)
> +{
> + StringInfoData param_str;
> +
> + /* No parameters to format */
> + if (!params || params->numParams == 0)
> + return NULL;
> +
> + elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d",
> +           params->hasTextValues && IsAbortedTransactionBlockState());

Err, huh?


Greetings,

Andres Freund

Reply | Threaded
Open this post in threaded view
|

Re: log bind parameter values on error

bashtanov
Hello Anders and Peter,

Thanks for your messages.
Please see the new patch version attached.

 > Have you analyzed how invasive it'd be to delay that till we actually
 > can safely start a [sub]transaction to do that logging? Probably too
 > expensive, but it seems like something that ought to be analyzed.

The fundamental problem here is that the output functions for the types
of the values to be logged may be present only in the transaction
that has just been aborted.

Also I don't like the idea of doing complex operations in the error handler,
as it increases the chances of cascading errors.

I thought of pre-calculating types' output functions instead of their
results,
but that would work for certain built-in types only.

>> +     <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
>> +      <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
>> +      <indexterm>
>> +       <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
>> +      </indexterm>
>> +      </term>
>> +      <listitem>
>> +       <para>
>> +        Controls whether the statement is logged with bind parameter values.
>> +        It adds some overhead, as postgres will cache textual
>> +        representations of parameter values in memory for all statements,
>> +        even if they eventually do not get logged. The default is
>> +        <literal>off</literal>. Only superusers can change this setting.
>> +       </para>
>> +      </listitem>
>> +     </varlistentry>
> This needs a bit of language polishing.
I would appreciate if you had any suggestions, as my English isn't great.

>> @@ -31,6 +31,8 @@
>>    * set of parameter values.  If dynamic parameter hooks are present, we
>>    * intentionally do not copy them into the result.  Rather, we forcibly
>>    * instantiate all available parameter values and copy the datum values.
>> + *
>> + * We don't copy textual representations here.
>>    */
> That probably needs to be expanded on. Including a comment about what
> guarantees that there are no memory lifetime issues.

What kind of memory lifetime issues do you mean?
We're not copying textual representations, so the worst can happen
is they don't get logged when appropriate. Luckily, we never use this
function when copying to a portal we use for logging, I added this to
the comment. Do you think it's any better?

>
> So the parameters we log here haven't actually gone through the output
> function? Isn't that an issue? I mean that'll cause the contents to
> differ from the non-error case, no? And differs from the binary protocol
> case?
I don't think it's much of a problem. Text input and output functions are
meant to match, but the CREATE TYPE spec isn't too specific about what
it means.
Of course it does not mean that typoutput(typinput(foo)) is always
exactly foo.
However, I really hope that at least typinput(typoutput(foo)) = foo,
where "=" is the correspondent operator registered in postgres.

If a cheeky client passes '007' as a numeric value I don't mind it being
sometimes logged as '007' and sometimes as '7', depending on the settings.
It anyway denotes the same number, and we'll know what to pass to
reproduce the problem.
For binary protocol it'll be '7' as well, as it'll undergo the typrecv
and then typoutput procedures.

>>   else
>>   {
>> + /*
>> + * We do it for non-xact commands only, as an xact command
>> + * 1) shouldn't have any parameters to log;
>> + * 2) may have the portal dropped early.
>> + */
>> + Assert(current_top_portal == NULL);
>> + current_top_portal = portal;
>> + portalParams = NULL;
>> +
> "it"? ISTM the comment doesn't really stand on its own?
Thanks, I fixed the comment and some code around it.

>> +/*
>> + * get_portal_bind_parameters
>> + * Get the string containing parameters data, is used for logging.
>> + *
>> + * Can return NULL if there are no parameters in the portal
>> + * or the portal is not valid, or the text representations of the parameters are
>> + * not available. If returning a non-NULL value, it allocates memory
>> + * for the returned string in the current context, and it's the caller's
>> + * responsibility to pfree() it if needed.
>> + */
>> +char *
>> +get_portal_bind_parameters(ParamListInfo params)
>> +{
>> + StringInfoData param_str;
>> +
>> + /* No parameters to format */
>> + if (!params || params->numParams == 0)
>> + return NULL;
>> +
>> + elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d",
>> +           params->hasTextValues && IsAbortedTransactionBlockState());
> Err, huh?
This was some debugging, I threw it away now.

Best,
  Alex


log_parameters_v006.patch (20K) Download Attachment