Re: Problems with extended-Query logging code

I happened to notice that the recently added code to log Bind-message
parameters was printing garbage into my log. On investigation it turned
out to be trying to print an already-pfree'd string. That's fixable,
but having looked at the code closely, I see a bunch of other stuff I'm
not happy about either:
* It's overly verbose: printing the same parameters twice seems
excessive.
* It's inefficient: it's spending effort on formatting and copying
parameter information around, whether or not there's any chance of
that information ever being wanted.
* It doesn't log the values of parameters sent in binary mode, which
is something that at least JDBC needs.

Another issue, which isn't the fault of the recent patches but has been
there right along, is that execution of Parse or Bind could take awhile
(due to planning of a complex query) but there's no log_duration or
log_min_duration_statement coverage for these message types.

Here are some thoughts about fixing it:

* For extended-Query mode I propose that we treat log_duration and
log_min_duration_statement as being effectively per-message not
per-statement. That is, we'd log a Parse or Bind operation if it
individually exceeded the duration threshold, and not otherwise.

* I'm inclined to think that Parse and Bind shouldn't be logged at all,
or maybe only at DEBUG2 or higher, unless logged by duration logging.
If we've got support for logging the statement text and the parameter
values at Execute time, isn't logging the preliminary steps just
bloating the log?

* I think that the best way to log bind-parameter values is to run the
datatype output functions on the saved parameter values. This works
whether they were sent in text or binary mode, and avoids any extra
overhead at Bind time that might not be repaid.

Comments?

regards, tom lane

On 6-Sep-06, at 6:01 PM, Tom Lane wrote:

> I happened to notice that the recently added code to log Bind-message
> parameters was printing garbage into my log. On investigation it
> turned
> out to be trying to print an already-pfree'd string. That's fixable,
> but having looked at the code closely, I see a bunch of other stuff
> I'm
> not happy about either:
> * It's overly verbose: printing the same parameters twice seems
> excessive.
> * It's inefficient: it's spending effort on formatting and copying
> parameter information around, whether or not there's any chance of
> that information ever being wanted.
> * It doesn't log the values of parameters sent in binary mode, which
> is something that at least JDBC needs.

AFAIK, we don't need binary mode right away, currently we only send
bytea parameters in binary mode

If we could get the text parameters it would be a big win.

>
> Another issue, which isn't the fault of the recent patches but has
> been
> there right along, is that execution of Parse or Bind could take
> awhile
> (due to planning of a complex query) but there's no log_duration or
> log_min_duration_statement coverage for these message types.
>
> Here are some thoughts about fixing it:
>
> * For extended-Query mode I propose that we treat log_duration and
> log_min_duration_statement as being effectively per-message not
> per-statement. That is, we'd log a Parse or Bind operation if it
> individually exceeded the duration threshold, and not otherwise.
>
> * I'm inclined to think that Parse and Bind shouldn't be logged at
> all,
> or maybe only at DEBUG2 or higher, unless logged by duration logging.
> If we've got support for logging the statement text and the parameter
> values at Execute time, isn't logging the preliminary steps just
> bloating the log?
>
> * I think that the best way to log bind-parameter values is to run the
> datatype output functions on the saved parameter values. This works
> whether they were sent in text or binary mode, and avoids any extra
> overhead at Bind time that might not be repaid.
>
> Comments?
>
> regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match
>

Dave Cramer <pg(at)fastcrypt(dot)com> writes:
> On 6-Sep-06, at 6:01 PM, Tom Lane wrote:
>> * It doesn't log the values of parameters sent in binary mode, which
>> is something that at least JDBC needs.

> AFAIK, we don't need binary mode right away, currently we only send
> bytea parameters in binary mode

I thought somebody had mentioned that integers were also sent in binary
in the latest driver code? Can't find the archive entry right now though.

regards, tom lane

On 6-Sep-06, at 6:17 PM, Tom Lane wrote:

> Dave Cramer <pg(at)fastcrypt(dot)com> writes:
>> On 6-Sep-06, at 6:01 PM, Tom Lane wrote:
>>> * It doesn't log the values of parameters sent in binary mode, which
>>> is something that at least JDBC needs.
>
>> AFAIK, we don't need binary mode right away, currently we only send
>> bytea parameters in binary mode
>
> I thought somebody had mentioned that integers were also sent in
> binary
> in the latest driver code? Can't find the archive entry right now
> though.
>
> regards, tom lane
>
Checking the source code

boolean isBinary(int index) {
// Currently, only StreamWrapper uses the binary parameter
form.
return (paramValues[index -1] instanceof StreamWrapper);
}

So for now if we concentrate on text parameters, binary parameters
would be superfluous for the moment.

Dave

Tom Lane wrote:
> I happened to notice that the recently added code to log Bind-message
> parameters was printing garbage into my log. On investigation it turned
> out to be trying to print an already-pfree'd string. That's fixable,

Uh, can you show me where?

> but having looked at the code closely, I see a bunch of other stuff I'm
> not happy about either:
> * It's overly verbose: printing the same parameters twice seems
> excessive.

You mean printing the bind parameters on execute? I thought we wanted
lines to be self-contained, and they can suppress the hints.

> * It's inefficient: it's spending effort on formatting and copying
> parameter information around, whether or not there's any chance of
> that information ever being wanted.

The problem there was there was no way to know what the GUC setting was
going to be by the time you did the execute, so I always stored it. It
is possible that is excessive.

> * It doesn't log the values of parameters sent in binary mode, which
> is something that at least JDBC needs.

Right.

> Another issue, which isn't the fault of the recent patches but has been
> there right along, is that execution of Parse or Bind could take awhile
> (due to planning of a complex query) but there's no log_duration or
> log_min_duration_statement coverage for these message types.

Yea, I figured that the odds that a bind or execute would take greater
than a certain duration was very unlikely, and the overhead of computing
the timing is might be pretty large compared to the actual prepare/bind.

> Here are some thoughts about fixing it:
>
> * For extended-Query mode I propose that we treat log_duration and
> log_min_duration_statement as being effectively per-message not
> per-statement. That is, we'd log a Parse or Bind operation if it
> individually exceeded the duration threshold, and not otherwise.

If you think the overhead it worth it, go ahead.

> * I'm inclined to think that Parse and Bind shouldn't be logged at all,
> or maybe only at DEBUG2 or higher, unless logged by duration logging.
> If we've got support for logging the statement text and the parameter
> values at Execute time, isn't logging the preliminary steps just
> bloating the log?

Good point. I had not thought of that.

> * I think that the best way to log bind-parameter values is to run the
> datatype output functions on the saved parameter values. This works
> whether they were sent in text or binary mode, and avoids any extra
> overhead at Bind time that might not be repaid.

Yes, I didn't get into something that complicated, but it would be a
more complete solution.

--
Bruce Momjian bruce(at)momjian(dot)us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

On Wed, 6 Sep 2006, Tom Lane wrote:

> I thought somebody had mentioned that integers were also sent in binary
> in the latest driver code? Can't find the archive entry right now though.
>

Using the fastpath protocol integers and oids are sent as binary. I don't
know if that is related to this or logged at all.

Kris Jurka

At 2006-09-06 18:01:38 -0400, tgl(at)sss(dot)pgh(dot)pa(dot)us wrote:
>
> That is, we'd log a Parse or Bind operation if it individually
> exceeded the duration threshold, and not otherwise.

Ok.

> If we've got support for logging the statement text and the parameter
> values at Execute time, isn't logging the preliminary steps just
> bloating the log?

Agreed. Logging Parse/Bind only if they're particularly interesting
sounds good to me.

> * I think that the best way to log bind-parameter values is to run the
> datatype output functions on the saved parameter values. This works
> whether they were sent in text or binary mode, and avoids any extra
> overhead at Bind time that might not be repaid.

Great. (The logging of binary parameters is something I also... not
exactly _need_, but would be happy about.)

-- ams

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> Tom Lane wrote:
>> I happened to notice that the recently added code to log Bind-message
>> parameters was printing garbage into my log. On investigation it turned
>> out to be trying to print an already-pfree'd string. That's fixable,

> Uh, can you show me where?

I didn't trace it down yet, but what I saw was garbage printed at
Execute time in an assert-enabled build. I think the bind-parameter
string that's being saved in the portal for Execute to print is not
copied into the portal's context. Since I want to get rid of that bit
anyway it didn't seem critical to identify the exact bug.

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > Tom Lane wrote:
> >> I happened to notice that the recently added code to log Bind-message
> >> parameters was printing garbage into my log. On investigation it turned
> >> out to be trying to print an already-pfree'd string. That's fixable,
>
> > Uh, can you show me where?
>
> I didn't trace it down yet, but what I saw was garbage printed at
> Execute time in an assert-enabled build. I think the bind-parameter
> string that's being saved in the portal for Execute to print is not
> copied into the portal's context. Since I want to get rid of that bit
> anyway it didn't seem critical to identify the exact bug.

OK, thanks. I thought I was doing that with a pstrdup(), but it might
have been in the wrong context at the time. Thanks.

--
Bruce Momjian bruce(at)momjian(dot)us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +