Re: Exec statement logging

OK, new patch. I used portal->sourceText as Tom suggested, and checked
for NULL before printing. I put the original query in brackets in the
log output, patch attached.

I would like to also do this for server-side EXECUTE. I am have
attached a second version that does it by using the existing loop we use
to check for a match for log_statement patterns. The code checks for an
ExecuteStmt node, and saves the prepare string that matches the portal.
The system can't determine the actual prepare string, so I used the
debug_query_string for a server-side PREPARE --- previously it just had
a null for the prepare string. Also, rather than change the API for
pg_parse_query(), I use a global variable that I check after the
function call. Here is sample output with log_statement and
log_min_duration_statement enabled:

PREPARE xx AS SELECT 1;
LOG: statement: PREPARE xx AS SELECT 1;
LOG: duration: 1.102 ms statement: PREPARE xx AS SELECT 1;
PREPARE

EXECUTE xx;
LOG: statement: EXECUTE xx; [client PREPARE: PREPARE xx AS SELECT 1;]
LOG: duration: 0.990 ms statement: EXECUTE xx; [client PREPARE: PREPARE xx AS SELECT 1;]
?column?
----------
1
(1 row)

---------------------------------------------------------------------------

Simon Riggs wrote:
> On Sat, 2005-05-14 at 16:55 -0400, Bruce Momjian wrote:
> > Uh, I am confused by this. Your code test is:
> >
> > + if ((log_statement == LOGSTMT_ALL && save_log_duration) ||
> > + save_log_min_duration_statement)
> > + gettimeofday(&start_t, NULL);
> >
> > First, log_min_duration_statement == -1 turns off logging. Your test
> > would enable it for -1. Also, you added "log_statement == LOGSTMT_ALL",
> > but don't have a similar test lower down where gettimeofday is used, so
> > I don't understand its usage here, or why it would be used in this
> > place. The original test is:
> >
> > + if (save_log_duration || save_log_min_duration_statement != -1)
> > + gettimeofday(&start_t, NULL);
>
> Yes, that looks wrong. Thanks for your diligence. I'm sorry that you've
> had to both spot an error and recode for it, I was expecting to do that.
>
> > One thing you did was to log debug_query_string, but I don't see how
> > that could be the right value. I assume it would be empty in a
> > client-side execute, or be the previous query. I instead used "EXECUTE
> > portal_name" because that is what we are passed from the client.
>
> I used the debug_query_string because even in the EXEC case it is set,
> so that the SQL statement appears correctly in pg_stat_activity. It may
> look wrong, but it is there.
>
> That part, at least, is correct, since I have used the patch in tuning.
>
> Perhaps it is only there when stats_command_string is set?
>
> Setting the SQL string to be only EXECUTE portal_name makes the log
> output almost useless for query tuning, so please reconsider that.
> Perhaps you could include both the portal name and the SQL statement?
>
> Best Regards, Simon Riggs
>

--
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