Thread: log_statement and Parse/Bind

I notice that when using the extended query protocol, statement logging 
appears to happen only when a Parse message is received. This is less 
than ideal:

- statements can be logged that are not actually executed (i.e. a 
Parse/Bind with no corresponding Execute).
- if statements are re-executed without an intervening Parse (i.e. 
Parse/Bind/Execute/Bind/Execute/...), only the first execution is logged.

There's also a lesser problem with using parameterized queries: the 
actual parameter values used in a Bind are not visible. This is the same 
as the PREPARE/EXECUTE case, except that it's more likely to be done 
transparently by the client's interface library (so we can't just tell 
the application developer "don't do that, then!")

Are there any plans to change this? Should I look at making a change 
along the lines of logging the statement on the first Execute of a 
portal, instead of on Parse?

-O

Oliver Jowett wrote:
> I notice that when using the extended query protocol, statement logging 
> appears to happen only when a Parse message is received. This is less 
> than ideal:
> 
> - statements can be logged that are not actually executed (i.e. a 
> Parse/Bind with no corresponding Execute).
> - if statements are re-executed without an intervening Parse (i.e. 
> Parse/Bind/Execute/Bind/Execute/...), only the first execution is logged.
> 
> There's also a lesser problem with using parameterized queries: the 
> actual parameter values used in a Bind are not visible. This is the same 
> as the PREPARE/EXECUTE case, except that it's more likely to be done 
> transparently by the client's interface library (so we can't just tell 
> the application developer "don't do that, then!")
> 
> Are there any plans to change this? Should I look at making a change 
> along the lines of logging the statement on the first Execute of a 
> portal, instead of on Parse?

Well, at execute time, we don't have easy access to the original prepare
statement, especially at that stage in the code. Do you see anyway to
improve that?


--  Bruce Momjian                        |  http://candle.pha.pa.us pgman@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073
 

Bruce Momjian wrote:

> Well, at execute time, we don't have easy access to the original prepare
> statement, especially at that stage in the code. Do you see anyway to
> improve that?

We have portal->sourceText which looks like it should contain the 
original query.

(note that I'm talking about the V3 protocol Execute message, not the 
SQL EXECUTE command)

-o

Oliver Jowett <oliver@opencloud.com> writes:
> I notice that when using the extended query protocol, statement logging 
> appears to happen only when a Parse message is received. This is less 
> than ideal:

I agree, but I didn't have time at the end of the 7.4 development cycle
to work out what should happen.

I do not think that regurgitating the statement three times would make
anyone very happy, so some thought has to go into what's appropriate.
        regards, tom lane

Tom Lane wrote:
> Oliver Jowett <oliver@opencloud.com> writes:
> 
>>I notice that when using the extended query protocol, statement logging 
>>appears to happen only when a Parse message is received. This is less 
>>than ideal:
> 
> 
> I agree, but I didn't have time at the end of the 7.4 development cycle
> to work out what should happen.
> 
> I do not think that regurgitating the statement three times would make
> anyone very happy, so some thought has to go into what's appropriate.

Currently the statement-type-analysis and logging occur in 
pg_parse_query, which is called from:
  pg_parse_and_rewrite     from fmgr_sql_validator (parses for syntax/args/return types only)     from init_sql_fcache
(parsesfor syntax/args/return types only)  exec_simple_query (1)  exec_parse_message (2)  fmgr_sql_validator (parses
forsyntax only)  _SPI_execute (3)
 

Turning off logging in pg_parse_query only affects (1..3), the other 
cases we don't really want to log anyway (except perhaps in the case of 
an error).

For (1) we can log after the parse but before execution starts.
For (2) we can delay logging until the Execute message comes along; the 
original query text is stored in the portal.
For (3) we can delay logging until _SPI_execute_plan (or do it directly 
in _SPI_execute when plan == NULL); the original query text is stored in 
the _SPI_Plan.

Add a parse tree -> statement type helper function to do categorization 
of the parse trees (currently done in pg_parse_query). Store that type 
in the prepared statement (for exec_parse_message) or _SPI_Plan (for 
_SPI_execute) for later use when executing the query; exec_simple_query 
can use the result immediately.

This leaves only error handling. Currently, with log_statement = all 
statements get logged before parsing which is quite useful when tracking 
down parse errors. This doesn't work if we only log when the query is 
actually executed, since a query that doesn't parse can never get executed.

Maybe something like including the original query string as a field of 
errors encountered when parsing would do the trick? Or use an error 
callback to catch the error and log the statement before the real error 
is reported when log_statement = all?

-O