Thread: prepared statements don't log arguments?

prepared statements don't log arguments?

From
Palle Girgensohn
Date:
Hi!

When setting log_statement = all, and using JDBC PreparedStatements, I get 
$n in the log where the real arguments used to be in previous versions of 
postgresql:

postgres[30059]: [97-1] LOG:  statement: INSERT INTO group_data 
(this_group_id, item_text, link_path) VALUES ($1, $2, $3)


I really need to know the *real* arguments... How can I get them? Is it a 
bug?

/Palle



Re: prepared statements don't log arguments?

From
Greg Stark
Date:
Palle Girgensohn <girgen@pingpong.net> writes:

> When setting log_statement = all, and using JDBC PreparedStatements, I get $n
> in the log where the real arguments used to be in previous versions of
> postgresql:
> 
> postgres[30059]: [97-1] LOG:  statement: INSERT INTO group_data (this_group_id,
> item_text, link_path) VALUES ($1, $2, $3)
> 
> I really need to know the *real* arguments... How can I get them? Is it a bug?

The bug was that prepared statements didn't work properly in the past. That is
the statement you're actually running.

You might want to look into JDBC options to disable use of prepared
statements. The old emulation code must still be there in case it runs against
a <=7.4 database so perhaps there's an option to use it.

-- 
greg



Re: prepared statements don't log arguments?

From
Christopher Kings-Lynne
Date:
>>postgres[30059]: [97-1] LOG:  statement: INSERT INTO group_data (this_group_id,
>>item_text, link_path) VALUES ($1, $2, $3)
>>
>>I really need to know the *real* arguments... How can I get them? Is it a bug?
> 
> 
> The bug was that prepared statements didn't work properly in the past. That is
> the statement you're actually running.
> 
> You might want to look into JDBC options to disable use of prepared
> statements. The old emulation code must still be there in case it runs against
> a <=7.4 database so perhaps there's an option to use it.

I think he has a really excellent point.  It should log the parameters 
as well.

Chris


Re: prepared statements don't log arguments?

From
Neil Conway
Date:
Christopher Kings-Lynne wrote:
> I think he has a really excellent point.  It should log the parameters 
> as well.

neilc=# prepare foo(int, int) as select $1 + $2;
PREPARE
neilc=# execute foo(5, 10);
...
neilc=# execute foo(15, 20);
...

% tail /usr/local/pgsql/postmaster.log
LOG:  statement: prepare foo(int, int) as select $1 + $2;
LOG:  statement: execute foo(5, 10);
LOG:  statement: execute foo(15, 20);

-Neil


Re: prepared statements don't log arguments?

From
Abhijit Menon-Sen
Date:
At 2005-04-07 12:14:19 +1000, neilc@samurai.com wrote:
>
> % tail /usr/local/pgsql/postmaster.log
> LOG:  statement: prepare foo(int, int) as select $1 + $2;
> LOG:  statement: execute foo(5, 10);
> LOG:  statement: execute foo(15, 20);

If you send a v3 protocol execute message instead of an SQL EXECUTE
statement, the parameters don't get logged.

-- ams


Re: prepared statements don't log arguments?

From
Alvaro Herrera
Date:
On Thu, Apr 07, 2005 at 12:14:19PM +1000, Neil Conway wrote:
> Christopher Kings-Lynne wrote:
> >I think he has a really excellent point.  It should log the parameters 
> >as well.
> 
> neilc=# prepare foo(int, int) as select $1 + $2;
> PREPARE
> neilc=# execute foo(5, 10);
> ...
> neilc=# execute foo(15, 20);
> ...
> 
> % tail /usr/local/pgsql/postmaster.log
> LOG:  statement: prepare foo(int, int) as select $1 + $2;
> LOG:  statement: execute foo(5, 10);
> LOG:  statement: execute foo(15, 20);

Yeah, but I think he mentioned JDBC which (I think) uses the low-level
protocol and probably doesn't log the parameters as well (I notice that
his example has INSERT as the query, not PREPARE nor EXECUTE.)

-- 
Alvaro Herrera (<alvherre[@]dcc.uchile.cl>)
"I call it GNU/Linux. Except the GNU/ is silent." (Ben Reiter)


Re: prepared statements don't log arguments?

From
Oliver Jowett
Date:
Neil Conway wrote:
> Christopher Kings-Lynne wrote:
> 
>> I think he has a really excellent point.  It should log the parameters
>> as well.
> 
> 
> neilc=# prepare foo(int, int) as select $1 + $2;
> PREPARE
> neilc=# execute foo(5, 10);
> ...
> neilc=# execute foo(15, 20);
> ...
> 
> % tail /usr/local/pgsql/postmaster.log
> LOG:  statement: prepare foo(int, int) as select $1 + $2;
> LOG:  statement: execute foo(5, 10);
> LOG:  statement: execute foo(15, 20);

Query-level EXECUTE is logged, but Bind/Execute via the V3 extended
query protocol (which is what the JDBC driver does) isn't.

In fact, the logging for the extended query protocol really sucks: the
server logs only the Parse, and is silent about Bind/Execute, so there
are all sorts of strange cases where your statement logs do not reflect
what was actually executed at all. For example, the JDBC driver issues a
Parse (but no Execute!) when an application asks for type metadata from
a query, and it can issue multiple Bind/Executes for a single Parse.

I've raised this before on -hackers but haven't had time to do anything
about it myself yet.

-O


Re: prepared statements don't log arguments?

From
Neil Conway
Date:
Oliver Jowett wrote:
> Query-level EXECUTE is logged, but Bind/Execute via the V3 extended
> query protocol (which is what the JDBC driver does) isn't.

Ah, I see. Yes, that certainly needs to be fixed.

-Neil


Re: prepared statements don't log arguments?

From
Oliver Jowett
Date:
Greg Stark wrote:
> Palle Girgensohn <girgen@pingpong.net> writes:
> 
>>When setting log_statement = all, and using JDBC PreparedStatements, I get $n
>>in the log where the real arguments used to be in previous versions of
>>postgresql:

> You might want to look into JDBC options to disable use of prepared
> statements. The old emulation code must still be there in case it runs against
> a <=7.4 database so perhaps there's an option to use it.

You can do this by appending '?protocolVersion=2' to the JDBC URL you
use (or '&protocolVersion=2' if you already have other URL parameters).

If you do this you also lose any features that need V3 protocol support
(e.g. query parameter metadata and some resultset metadata).

-O


Re: prepared statements don't log arguments?

From
Tom Lane
Date:
Oliver Jowett <oliver@opencloud.com> writes:
> In fact, the logging for the extended query protocol really sucks:

Without doubt.  Someone has to sit down and think about exactly what
we should log, where when and how ... proposals welcome ...
        regards, tom lane


Re: prepared statements don't log arguments?

From
Palle Girgensohn
Date:
--On torsdag, april 07, 2005 14.34.22 +1200 Oliver Jowett 
<oliver@opencloud.com> wrote:

> Greg Stark wrote:
>> Palle Girgensohn <girgen@pingpong.net> writes:
>>
>>> When setting log_statement = all, and using JDBC PreparedStatements, I
>>> get $n in the log where the real arguments used to be in previous
>>> versions of postgresql:
>
>> You might want to look into JDBC options to disable use of prepared
>> statements. The old emulation code must still be there in case it runs
>> against a <=7.4 database so perhaps there's an option to use it.
>
> You can do this by appending '?protocolVersion=2' to the JDBC URL you
> use (or '&protocolVersion=2' if you already have other URL parameters).
>
> If you do this you also lose any features that need V3 protocol support
> (e.g. query parameter metadata and some resultset metadata).

OK, thanks. Still, I think I do need V3 stuff... Is it not possible to log 
the arguments, somehow? Seems strange?

/Palle



Re: prepared statements don't log arguments?

From
Simon Riggs
Date:
On Wed, 2005-04-06 at 15:01 +0200, Palle Girgensohn wrote:
> I really need to know the *real* arguments... 

Why do you need to log the arguments as well?

Thanks,

Best Regards, Simon Riggs



Re: prepared statements don't log arguments?

From
Palle Girgensohn
Date:
--On torsdag, april 07, 2005 23.31.52 +0100 Simon Riggs 
<simon@2ndquadrant.com> wrote:

> On Wed, 2005-04-06 at 15:01 +0200, Palle Girgensohn wrote:
>> I really need to know the *real* arguments...
>
> Why do you need to log the arguments as well?

Debugging purposes. If I fealize there are queries hogging the server, I'd 
like to get them from a log so I can tune the system, maybe add an index or 
find the qurey in the src code an rephrase it. It is *very* helpful to a 
proper set of arguments for a slow query, since another set of arguments 
will probably give a very speedy result. I need to find the hogs, basically.

/Palle





Re: prepared statements don't log arguments?

From
Simon Riggs
Date:
On Fri, 2005-04-08 at 00:51 +0200, Palle Girgensohn wrote:
> --On torsdag, april 07, 2005 23.31.52 +0100 Simon Riggs 
> <simon@2ndquadrant.com> wrote:
> 
> > On Wed, 2005-04-06 at 15:01 +0200, Palle Girgensohn wrote:
> >> I really need to know the *real* arguments...
> >
> > Why do you need to log the arguments as well?
> 
> Debugging purposes. If I fealize there are queries hogging the server, I'd 
> like to get them from a log so I can tune the system, maybe add an index or 
> find the qurey in the src code an rephrase it. It is *very* helpful to a 
> proper set of arguments for a slow query, since another set of arguments 
> will probably give a very speedy result. I need to find the hogs, basically.

OK, thats what I hoped you'd say. With a prepared query all of the
statements execute the same plan, so you don't need to know the exact
parameters. Before v3 the whole query was logged because the statements
were not prepared and each query might have been different. That is no
longer the case.

ISTM that for analysis purposes it is helpful to know that a particular
query is being repeated. Also, if you log the actual parameters, the log
gets unusefully large very quickly.

Anyway, I have a patch that I will be able to submit shortly in this
area. No doubt it will require further discussion.

Best Regards, Simon Riggs



Re: prepared statements don't log arguments?

From
Oliver Jowett
Date:
Simon Riggs wrote:

> OK, thats what I hoped you'd say. With a prepared query all of the
> statements execute the same plan, so you don't need to know the exact
> parameters.

This isn't true in 8.0 if you are using the unnamed statement (as the
JDBC driver does in some cases): the plan chosen depends on the
parameter values given in the first Bind.

-O


Re: prepared statements don't log arguments?

From
Tom Lane
Date:
Oliver Jowett <oliver@opencloud.com> writes:
> Simon Riggs wrote:
>> OK, thats what I hoped you'd say. With a prepared query all of the
>> statements execute the same plan, so you don't need to know the exact
>> parameters.

> This isn't true in 8.0 if you are using the unnamed statement (as the
> JDBC driver does in some cases): the plan chosen depends on the
> parameter values given in the first Bind.

Also, "what plan got chosen" isn't the only question that a DBA might
want the log to answer.  "Where did my data get screwed up" is at least
as likely an application.

I'm a bit worried about the costs of converting binary-format parameters
into text form ...
        regards, tom lane


Re: prepared statements don't log arguments?

From
Simon Riggs
Date:
> Oliver Jowett <oliver@opencloud.com> writes:
> > Simon Riggs wrote:
> >> OK, thats what I hoped you'd say. With a prepared query all of the
> >> statements execute the same plan, so you don't need to know the exact
> >> parameters.
> 
> > This isn't true in 8.0 if you are using the unnamed statement (as the
> > JDBC driver does in some cases): the plan chosen depends on the
> > parameter values given in the first Bind.

Oliver,

Yes, I was aware of that, but thought it would confuse the issue.

I agree that it would be ideal if the parameter values from the first
Bind were also logged. However, you don't often need the parameters to
do performance tuning. Initial profiling groups similar statements
together to find the hot spots. We may find other problems like
incorrect SQL, missing join clauses, missing WHERE clauses, need-an-
index etc. Most of which can be done without seeing the exact
parameters. Even if you suspect a wild first bind parameter as the cause
of performance problems, this is still fairly easy to trace - the
question of what do you do about it isn't helped a great deal by knowing
what the value is.

> On Fri, 2005-04-08 at 03:11 -0400, Tom Lane wrote:
> Also, "what plan got chosen" isn't the only question that a DBA might
> want the log to answer.  "Where did my data get screwed up" is at least
> as likely an application.
> 
> I'm a bit worried about the costs of converting binary-format parameters
> into text form ...

Tom

If we have separate requirements, surely they are best met with separate
GUC parameters. For performance analysis purposes we only need to see
the first parameter set, if ever; but we never need to see all of the
parameters.

If we had a log_parameters statements with options:log_parameters = none | first | all
This would give you the capability to log the data as well, if you
required this.

As you point out, there would be performance implications to logging all
of the parameters including both CPU overhead and log volume. There is
also another implication of Data Protection, since you wouldn't
necessarily want to show all people seeing the log your data details.

Anyway, I don't personally see a need or benefit to log parameters in
any case, so I'm happy if anybody wants to raise a TODO item from this,
but its not me.

I've got a patch to submit that logs the EXEC phase, so you get just the
SQL, not the parameters. When we last spoke about this [on ADMIN during
Feb] you mentioned that one of the main reasons that this was not done
before was people couldn't agree exactly how to proceed. In the
meantime, logging just the SQL takes us 95% of the way along the road we
wish to travel.

Best Regards, Simon Riggs



Re: prepared statements don't log arguments?

From
Oliver Jowett
Date:
Simon Riggs wrote:

> I've got a patch to submit that logs the EXEC phase, so you get just the
> SQL, not the parameters. [...]

I assume this replaces the current logging on Parse to avoid duplicate
logging?

What happens on syntax errors? It's useful to log the statement that
failed, but you will need some trickery there since if the Parse logging
goes away, we won't have logged anything at the point the error is
generated.

-O


Re: prepared statements don't log arguments?

From
Simon Riggs
Date:
On Sun, 2005-04-10 at 17:54 +1200, Oliver Jowett wrote:
> Simon Riggs wrote:
> 
> > I've got a patch to submit that logs the EXEC phase, so you get just the
> > SQL, not the parameters. [...]

Just testing against cvstip and wrapping now...

> I assume this replaces the current logging on Parse to avoid duplicate
> logging?

Well, I'm open to discussion, but that isn't what the patch does.

My thinking was to add functionality, not take it away. We currently
support V2 and V3 connections, so we need to continue to log V2
statements as well as V3 exec phase.

> What happens on syntax errors? It's useful to log the statement that
> failed, but you will need some trickery there since if the Parse logging
> goes away, we won't have logged anything at the point the error is
> generated.

Well, those are problems I've not had to solve.

Best Regards, Simon Riggs




Re: prepared statements don't log arguments?

From
Oliver Jowett
Date:
Simon Riggs wrote:

>>I assume this replaces the current logging on Parse to avoid duplicate
>>logging?
> 
> 
> Well, I'm open to discussion, but that isn't what the patch does.

I guess I'll wait for your patch and take a look rather than try to
guess about what it does, then.

> My thinking was to add functionality, not take it away. We currently
> support V2 and V3 connections, so we need to continue to log V2
> statements as well as V3 exec phase.

V2 is like the V3 simple query case..

-O