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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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(at)opencloud(dot)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(at)opencloud(dot)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 (parses for syntax/args/return types only)
exec_simple_query (1)
exec_parse_message (2)
fmgr_sql_validator (parses for syntax 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