Thread: prepared statements don't log arguments?
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
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
>>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
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
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
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)
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
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
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
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
--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
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
--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
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
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
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
> 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
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
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
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